From 92a641f86b4e473f7d5bbc0e69212706817d0003 Mon Sep 17 00:00:00 2001 From: Zachary Dremann Date: Sun, 3 Sep 2017 01:18:08 -0400 Subject: [PATCH 1/5] Add some benchmarks --- Cargo.toml | 1 + benches/common/mod.rs | 40 ++++++++++++++++++++++++++++++++++++++++ benches/junk_modules.rs | 29 +++++++++++++++++++++++++++++ benches/quiet.rs | 25 +++++++++++++++++++++++++ benches/real_calls.rs | 24 ++++++++++++++++++++++++ benches/skip_module.rs | 28 ++++++++++++++++++++++++++++ benches/util/mod.rs | 30 ++++++++++++++++++++++++++++++ 7 files changed, 177 insertions(+) create mode 100644 benches/common/mod.rs create mode 100644 benches/junk_modules.rs create mode 100644 benches/quiet.rs create mode 100644 benches/real_calls.rs create mode 100644 benches/skip_module.rs create mode 100644 benches/util/mod.rs diff --git a/Cargo.toml b/Cargo.toml index 646fe5be..17a1e258 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -17,3 +17,4 @@ time = "0.1" [dev-dependencies] docopt = "0.6" rustc-serialize = "0.3" +libc = "0.2" diff --git a/benches/common/mod.rs b/benches/common/mod.rs new file mode 100644 index 00000000..84e91b88 --- /dev/null +++ b/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); + }) + })); +} \ No newline at end of file diff --git a/benches/junk_modules.rs b/benches/junk_modules.rs new file mode 100644 index 00000000..d1764f77 --- /dev/null +++ b/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(); + }); +} \ No newline at end of file diff --git a/benches/quiet.rs b/benches/quiet.rs new file mode 100644 index 00000000..2ae470a9 --- /dev/null +++ b/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(); + }); +} \ No newline at end of file diff --git a/benches/real_calls.rs b/benches/real_calls.rs new file mode 100644 index 00000000..cc803eea --- /dev/null +++ b/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(); + }); +} \ No newline at end of file diff --git a/benches/skip_module.rs b/benches/skip_module.rs new file mode 100644 index 00000000..80623e51 --- /dev/null +++ b/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(); + }); +} \ No newline at end of file diff --git a/benches/util/mod.rs b/benches/util/mod.rs new file mode 100644 index 00000000..3f12f630 --- /dev/null +++ b/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(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), + } +} From ecb7f3699a947bae6aa3a665beb72ad98757b86c Mon Sep 17 00:00:00 2001 From: Zachary Dremann Date: Sat, 2 Sep 2017 20:47:58 -0400 Subject: [PATCH 2/5] Do not require .init() to be called. Use the verbosity which is stored to check if a level is enabled --- src/lib.rs | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index efc441ba..c6154bbc 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -87,7 +87,7 @@ pub struct StdErrLog { 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) { @@ -164,14 +164,18 @@ impl StdErrLog { self } + fn log_level_filter(&self) -> LogLevelFilter { + if self.quiet { + LogLevelFilter::Off + } else { + self.verbosity + } + } + 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()) }) From 71e2f619f2fe6f4726cf5ea1396f0fb76d5998ae Mon Sep 17 00:00:00 2001 From: Zachary Dremann Date: Sat, 2 Sep 2017 21:22:48 -0400 Subject: [PATCH 3/5] Only format the timestamp if about to output --- src/lib.rs | 18 ++++++------------ 1 file changed, 6 insertions(+), 12 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index c6154bbc..c7ae9670 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -66,7 +66,7 @@ extern crate log; extern crate time; use log::{LogLevelFilter, LogMetadata}; -use std::io::Write; +use std::io::{self, Write}; /// State of the timestampping in the logger. #[derive(Clone, Copy, Debug)] @@ -100,21 +100,15 @@ 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()); + let mut writer = io::LineWriter::new(io::stderr()); + if let Timestamp::Second = self.timestamp { + let _ = write!(writer, "{} - ", time::now().rfc3339()); + } + let _ = writeln!(writer, "{} - {}", record.level(), record.args()); } } } From fa6ce7235218ef9a7b2bb1ad32c1c04edb107b72 Mon Sep 17 00:00:00 2001 From: Zachary Dremann Date: Sat, 2 Sep 2017 22:28:43 -0400 Subject: [PATCH 4/5] Line buffer stderr when writing This should reduce the number of syscalls, and locks around stderr --- Cargo.toml | 1 + src/lib.rs | 22 ++++++++++++++++++++-- 2 files changed, 21 insertions(+), 2 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 17a1e258..3422e1b5 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -13,6 +13,7 @@ version = "0.2.2" [dependencies] log = "0.3" time = "0.1" +thread_local = "0.3" [dev-dependencies] docopt = "0.6" diff --git a/src/lib.rs b/src/lib.rs index c7ae9670..9e4438a4 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -64,7 +64,10 @@ 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::{self, Write}; @@ -77,12 +80,25 @@ pub enum Timestamp { Second, } -#[derive(Clone, Debug)] +#[derive(Debug)] pub struct StdErrLog { verbosity: LogLevelFilter, quiet: bool, timestamp: Timestamp, modules: Vec, + writer: CachedThreadLocal>>, +} + +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 { @@ -104,7 +120,8 @@ impl log::Log for StdErrLog { // 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 mut writer = io::LineWriter::new(io::stderr()); + 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()); } @@ -120,6 +137,7 @@ impl StdErrLog { quiet: false, timestamp: Timestamp::Off, modules: vec![], + writer: CachedThreadLocal::new(), } } From 767d4554e7432493be66789d88229fc9fd90a69f Mon Sep 17 00:00:00 2001 From: Zachary Dremann Date: Sun, 3 Sep 2017 01:18:36 -0400 Subject: [PATCH 5/5] Search modules with a BTreeSet instead of a Vec linear search --- src/lib.rs | 30 +++++++++++++++++++++++------- 1 file changed, 23 insertions(+), 7 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index 9e4438a4..f079b619 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -70,6 +70,8 @@ use thread_local::CachedThreadLocal; use std::cell::RefCell; use log::{LogLevelFilter, LogMetadata}; use std::io::{self, Write}; +use std::collections::BTreeSet; +use std::collections::Bound; /// State of the timestampping in the logger. #[derive(Clone, Copy, Debug)] @@ -85,7 +87,7 @@ pub struct StdErrLog { verbosity: LogLevelFilter, quiet: bool, timestamp: Timestamp, - modules: Vec, + modules: BTreeSet, writer: CachedThreadLocal>>, } @@ -119,7 +121,7 @@ impl log::Log for StdErrLog { // 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)) { + 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 { @@ -136,7 +138,7 @@ impl StdErrLog { verbosity: LogLevelFilter::Error, quiet: false, timestamp: Timestamp::Off, - modules: vec![], + modules: BTreeSet::new(), writer: CachedThreadLocal::new(), } } @@ -167,12 +169,12 @@ 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) -> &mut StdErrLog { - self.modules.extend(modules); + pub fn modules, I: IntoIterator>(&mut self, modules: I) -> &mut StdErrLog { + self.modules.extend(modules.into_iter().map(Into::into)); self } @@ -184,8 +186,22 @@ impl StdErrLog { } } - pub fn init(&self) -> Result<(), log::SetLoggerError> { + 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::((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| { max_log_level.set(self.log_level_filter());