Improvements

Cargo.toml

@@ -13,7 +13,9 @@ version = "0.2.2"
 [dependencies]
 log = "0.3"
 time = "0.1"
+thread_local = "0.3"
 
 [dev-dependencies]
 docopt = "0.6"
 rustc-serialize = "0.3"
+libc = "0.2"

benches/common/mod.rs

@@ -0,0 +1,40 @@
+use std::panic;
+use test::Bencher;
+
+use util::with_redirected_stderr;
+use init_logger;
+
+#[bench]
+fn simple_string(b: &mut Bencher) {
+    init_logger();
+    with_redirected_stderr(panic::AssertUnwindSafe(|| {
+        b.iter(|| {
+            debug!("Whoami");
+        });
+    }));
+}
+
+#[bench]
+fn complex_format(b: &mut Bencher) {
+    init_logger();
+    with_redirected_stderr(panic::AssertUnwindSafe(|| {
+        b.iter(|| {
+            debug!("{}, {:#?}, {:b}", 0.1f64, vec![99, 1, 5, 100, 1, 0, 8], 0xffb1aa)
+        })
+    }));
+}
+
+#[bench]
+fn long_line(b: &mut Bencher) {
+    let mut long_data = vec![];
+    for _ in 0..1_000 {
+        long_data.push("this is an item in a long list");
+    }
+
+    init_logger();
+    with_redirected_stderr(panic::AssertUnwindSafe(|| {
+        b.iter(|| {
+            debug!("long data: {:?}", long_data);
+        })
+    }));
+}

benches/junk_modules.rs

@@ -0,0 +1,29 @@
+#![feature(test)]
+extern crate test;
+extern crate stderrlog;
+extern crate libc;
+
+#[macro_use]
+extern crate log;
+
+mod util;
+mod common;
+
+use std::sync;
+
+static INIT_LOGGER: sync::Once = sync::ONCE_INIT;
+
+fn init_logger() {
+    INIT_LOGGER.call_once(|| {
+        let mut other_modules = Vec::new();
+        for i in 0..10_000 {
+            other_modules.push(format!("other::mod{}", i));
+        }
+        other_modules.push(format!("{}::common", module_path!()));
+        stderrlog::StdErrLog::new()
+            .timestamp(stderrlog::Timestamp::Second)
+            .verbosity(10)
+            .modules(other_modules)
+            .init().unwrap();
+    });
+}

benches/quiet.rs

@@ -0,0 +1,25 @@
+#![feature(test)]
+extern crate test;
+extern crate stderrlog;
+extern crate libc;
+
+#[macro_use]
+extern crate log;
+
+mod util;
+mod common;
+
+use std::sync;
+
+static INIT_LOGGER: sync::Once = sync::ONCE_INIT;
+
+fn init_logger() {
+    INIT_LOGGER.call_once(|| {
+        stderrlog::StdErrLog::new()
+            .timestamp(stderrlog::Timestamp::Second)
+            .verbosity(10)
+            .quiet(true)
+            .module(module_path!())
+            .init().unwrap();
+    });
+}

benches/real_calls.rs

@@ -0,0 +1,24 @@
+#![feature(test)]
+extern crate test;
+extern crate stderrlog;
+extern crate libc;
+
+#[macro_use]
+extern crate log;
+
+mod util;
+mod common;
+
+use std::sync;
+
+static INIT_LOGGER: sync::Once = sync::ONCE_INIT;
+
+fn init_logger() {
+    INIT_LOGGER.call_once(|| {
+        stderrlog::StdErrLog::new()
+            .timestamp(stderrlog::Timestamp::Second)
+            .verbosity(10)
+            .module(module_path!())
+            .init().unwrap();
+    });
+}

benches/skip_module.rs

@@ -0,0 +1,28 @@
+#![feature(test)]
+extern crate test;
+extern crate stderrlog;
+extern crate libc;
+
+#[macro_use]
+extern crate log;
+
+mod util;
+mod common;
+
+use std::sync;
+
+static INIT_LOGGER: sync::Once = sync::ONCE_INIT;
+
+fn init_logger() {
+    INIT_LOGGER.call_once(|| {
+        let mut other_modules = Vec::new();
+        for i in 0..10_000 {
+            other_modules.push(format!("other::mod{}", i));
+        }
+        stderrlog::StdErrLog::new()
+            .timestamp(stderrlog::Timestamp::Second)
+            .verbosity(10)
+            .modules(other_modules)
+            .init().unwrap();
+    });
+}

benches/util/mod.rs

@@ -0,0 +1,30 @@
+use std::panic;
+use std::fs::File;
+use std::os::unix::io::AsRawFd;
+use libc;
+
+pub fn with_redirected_stderr<T, F>(f: F) -> T
+where
+    F: FnOnce() -> T,
+    F: panic::UnwindSafe,
+{
+    let file = File::create("/dev/null").unwrap();
+    let fd = file.as_raw_fd();
+    let orig_fd = unsafe {
+        let orig_fd = libc::dup(2);
+        assert!(orig_fd >= 0);
+        let rc = libc::dup2(fd, 2);
+        assert!(rc >= 0);
+        orig_fd
+    };
+    drop(file);
+    let result = panic::catch_unwind(f);
+    unsafe {
+        libc::dup2(orig_fd, 2);
+        libc::close(orig_fd);
+    }
+    match result {
+        Ok(t) => t,
+        Err(e) => panic::resume_unwind(e),
+    }
+}

src/lib.rs

@@ -64,9 +64,14 @@
 
 extern crate log;
 extern crate time;
+extern crate thread_local;
 
+use thread_local::CachedThreadLocal;
+use std::cell::RefCell;
 use log::{LogLevelFilter, LogMetadata};
-use std::io::Write;
+use std::io::{self, Write};
+use std::collections::BTreeSet;
+use std::collections::Bound;
 
 /// State of the timestampping in the logger.
 #[derive(Clone, Copy, Debug)]
@@ -77,17 +82,30 @@ pub enum Timestamp {
     Second,
 }
 
-#[derive(Clone, Debug)]
+#[derive(Debug)]
 pub struct StdErrLog {
     verbosity: LogLevelFilter,
     quiet: bool,
     timestamp: Timestamp,
-    modules: Vec<String>,
+    modules: BTreeSet<String>,
+    writer: CachedThreadLocal<RefCell<io::LineWriter<io::Stderr>>>,
+}
+
+impl Clone for StdErrLog {
+    fn clone(&self) -> StdErrLog {
+        StdErrLog {
+            verbosity: self.verbosity,
+            quiet: self.quiet,
+            timestamp: self.timestamp,
+            modules: self.modules.clone(),
+            writer: CachedThreadLocal::new(),
+        }
+    }
 }
 
 impl log::Log for StdErrLog {
     fn enabled(&self, metadata: &LogMetadata) -> bool {
-        metadata.level() <= log::max_log_level()
+        metadata.level() <= self.log_level_filter()
     }
 
     fn log(&self, record: &log::LogRecord) {
@@ -100,21 +118,16 @@ impl log::Log for StdErrLog {
         // module we are logging for
         let curr_mod = record.location().module_path();
 
-        // create the timestamp prefix string
-        let timestamp_prefix = match self.timestamp {
-            Timestamp::Off => String::new(),
-            Timestamp::Second => format!("{} - ", time::now().rfc3339()),
-        };
-
         // this logger only logs the requested modules unless the
         // vector of modules is empty
         // modules will have module::file in the module_path
-        if self.modules.is_empty() || self.modules.iter().any(|x| curr_mod.starts_with(x)) {
-            let _ = writeln!(&mut ::std::io::stderr(),
-                             "{}{} - {}",
-                             timestamp_prefix,
-                             record.level(),
-                             record.args());
+        if self.includes_module(curr_mod) {
+            let writer = self.writer.get_or(|| Box::new(RefCell::new(io::LineWriter::new(io::stderr()))));
+            let mut writer = writer.borrow_mut();
+            if let Timestamp::Second = self.timestamp {
+                let _ = write!(writer, "{} - ", time::now().rfc3339());
+            }
+            let _ = writeln!(writer, "{} - {}", record.level(), record.args());
         }
     }
 }
@@ -125,7 +138,8 @@ impl StdErrLog {
             verbosity: LogLevelFilter::Error,
             quiet: false,
             timestamp: Timestamp::Off,
-            modules: vec![],
+            modules: BTreeSet::new(),
+            writer: CachedThreadLocal::new(),
         }
     }
 
@@ -155,23 +169,41 @@ impl StdErrLog {
     }
 
     pub fn module(&mut self, module: &str) -> &mut StdErrLog {
-        self.modules.push(module.to_owned());
+        self.modules.insert(module.to_owned());
         self
     }
 
-    pub fn modules(&mut self, modules: Vec<String>) -> &mut StdErrLog {
-        self.modules.extend(modules);
+    pub fn modules<T: Into<String>, I: IntoIterator<Item=T>>(&mut self, modules: I) -> &mut StdErrLog {
+        self.modules.extend(modules.into_iter().map(Into::into));
         self
     }
 
-    pub fn init(&self) -> Result<(), log::SetLoggerError> {
+    fn log_level_filter(&self) -> LogLevelFilter {
+        if self.quiet {
+            LogLevelFilter::Off
+        } else {
+            self.verbosity
+        }
+    }
+
+    fn includes_module(&self, module_path: &str) -> bool {
+        // If modules is empty, include all module paths
+        if self.modules.is_empty() {
+            return true;
+        }
+        // if a prefix of module_path is in `self.modules`, it must be located at the first location before
+        // where module_path would be.
+        let mut iter = self.modules.range::<str, _>((Bound::Unbounded, Bound::Included(module_path)));
+        if let Some(prev) = iter.next_back() {
+            module_path.starts_with(prev)
+        } else {
+            false
+        }
+    }
 
+    pub fn init(&self) -> Result<(), log::SetLoggerError> {
         log::set_logger(|max_log_level| {
-            if self.quiet {
-                max_log_level.set(LogLevelFilter::Off);
-            } else {
-                max_log_level.set(self.verbosity);
-            }
+            max_log_level.set(self.log_level_filter());
 
             Box::new(self.clone())
         })