From 7e5398799894edfa23d2fdb02cc57c9195245081 Mon Sep 17 00:00:00 2001 From: Lars Wirzenius Date: Mon, 6 Dec 2021 21:25:05 +0200 Subject: feat: add logging A lot of logging, if the debug level is chosen. But that's how it should be. Sponsored-by: author --- Cargo.lock | 49 ++++++++++++++++++++++++++++++++++++++++++++++ Cargo.toml | 2 ++ src/bin/obnam-benchmark.rs | 12 ++++++++++++ src/data.rs | 31 ++++++++++++++++++++++------- src/run.rs | 3 --- src/state.rs | 15 +++++++++++--- 6 files changed, 99 insertions(+), 13 deletions(-) delete mode 100644 src/run.rs diff --git a/Cargo.lock b/Cargo.lock index e9af5eb..4928489 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -230,6 +230,19 @@ version = "1.6.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e78d4f1cc4ae33bbfc157ed5d5a5ef3bc29227303d595861deb238fcec4e9457" +[[package]] +name = "env_logger" +version = "0.7.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36" +dependencies = [ + "atty", + "humantime", + "log", + "regex", + "termcolor", +] + [[package]] name = "fake-simd" version = "0.1.2" @@ -415,6 +428,15 @@ version = "1.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "02296996cb8796d7c6e3bc2d9211b7802812d36999a51bb754123ead7d37d026" +[[package]] +name = "humantime" +version = "1.3.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f" +dependencies = [ + "quick-error", +] + [[package]] name = "ignore" version = "0.4.18" @@ -581,6 +603,8 @@ dependencies = [ "anyhow", "fehler", "glob", + "log", + "pretty_env_logger", "serde", "serde_json", "serde_yaml", @@ -743,6 +767,16 @@ version = "0.2.15" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ed0cfbc8191465bed66e1718596ee0b0b35d5ee1f41c5df2189d0fe8bde535ba" +[[package]] +name = "pretty_env_logger" +version = "0.4.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d" +dependencies = [ + "env_logger", + "log", +] + [[package]] name = "proc-macro-error" version = "1.0.4" @@ -788,6 +822,12 @@ dependencies = [ "unicase", ] +[[package]] +name = "quick-error" +version = "1.2.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a1d01941d82fa2ab50be1e79e6714289dd7cde78eba4c074bc5a4374f650dfe0" + [[package]] name = "quote" version = "1.0.10" @@ -1241,6 +1281,15 @@ dependencies = [ "unic-segment", ] +[[package]] +name = "termcolor" +version = "1.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4" +dependencies = [ + "winapi-util", +] + [[package]] name = "textwrap" version = "0.11.0" diff --git a/Cargo.toml b/Cargo.toml index 4bce24c..bb00a15 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -8,6 +8,8 @@ edition = "2018" [dependencies] anyhow = "1.0.51" +log = "0.4.14" +pretty_env_logger = "0.4.0" serde = { version = "1.0.101", features = ["derive"] } serde_json = "1.0.72" serde_yaml = "0.8.21" diff --git a/src/bin/obnam-benchmark.rs b/src/bin/obnam-benchmark.rs index 0ad8491..76ab620 100644 --- a/src/bin/obnam-benchmark.rs +++ b/src/bin/obnam-benchmark.rs @@ -1,3 +1,4 @@ +use log::{debug, error, info}; use obnam_benchmark::result::Result; use obnam_benchmark::specification::Specification; use obnam_benchmark::state::State; @@ -7,14 +8,20 @@ use std::process::exit; use structopt::StructOpt; fn main() { + pretty_env_logger::init_custom_env("OBNAM_BENCHMARK_LOG"); + info!("obnam-benchmark starts"); if let Err(err) = real_main() { eprintln!("ERROR: {}", err); + error!("{}", err); exit(1); } + info!("obnam-benchmark ends successfully"); } fn real_main() -> anyhow::Result<()> { + debug!("parsing command line"); let opt = Opt::from_args(); + debug!("parsed: {:#?}", opt); match opt.cmd { Command::Run(x) => x.run()?, @@ -52,6 +59,7 @@ struct Run { impl Run { fn run(&self) -> anyhow::Result<()> { + info!("running benchmarks from {}", self.spec.display()); let spec = Specification::from_file(&self.spec)?; let mut state = State::new()?; let mut result = Result::default(); @@ -60,6 +68,7 @@ impl Run { result.push(m); } } + debug!("writing results to {}", self.output.display()); let output = File::create(&self.output)?; serde_json::to_writer_pretty(&output, &result)?; Ok(()) @@ -79,9 +88,12 @@ struct Spec { impl Spec { fn run(&self) -> anyhow::Result<()> { + info!("dumping specification file as JSON"); + debug!("reading specification from {}", self.spec.display()); let input = File::open(&self.spec)?; let spec: Specification = serde_yaml::from_reader(&input)?; + debug!("writing specification as JSON to {}", self.output.display()); let output = File::create(&self.output)?; serde_json::to_writer(&output, &spec)?; diff --git a/src/data.rs b/src/data.rs index dbea40f..2069110 100644 --- a/src/data.rs +++ b/src/data.rs @@ -1,4 +1,5 @@ use crate::specification::{Create, FileCount}; +use log::debug; use std::fs::File; use std::path::{Path, PathBuf}; use tempfile::{tempdir_in, TempDir}; @@ -37,31 +38,36 @@ pub enum DataError { impl Data { pub(crate) fn new(tempdir: &Path) -> Result { let live = tempdir_in(&tempdir)?; - Ok(Self { - live, - }) + debug!("created temporary directory {}", live.path().display()); + Ok(Self { live }) } pub(crate) fn create(&self, create: &Create) -> Result<(), DataError> { - println!("create {:?} in {}", create, self.live.path().display()); + debug!( + "creating {} files in {}", + create.files, + self.live.path().display() + ); for i in 0..create.files { let filename = self.live.path().join(format!("{}", i)); + debug!("creating {}", filename.display()); File::create(&filename).map_err(|err| DataError::CreateFile(filename, err))?; } Ok(()) } pub(crate) fn rename(&self, count: &FileCount) -> Result<(), DataError> { - println!("rename {:?}", count); + debug!("renaming {} files", count.files); Ok(()) } pub(crate) fn delete(&self, count: &FileCount) -> Result<(), DataError> { - println!("delete {:?}", count); + debug!("deleting {}", count.files); Ok(()) } pub(crate) fn file_count(&self) -> Result { + debug!("counting files in {}", self.live.path().display()); let mut n = 0; for entry in WalkDir::new(&self.live).into_iter() { if let Err(err) = entry { @@ -69,10 +75,21 @@ impl Data { } n += 1; } + debug!("found {} files in {}", n, self.live.path().display()); Ok(n) } pub(crate) fn file_size(&self) -> Result { - Ok(0) + debug!( + "counting combined slze of files in {}", + self.live.path().display() + ); + let n = 0; + debug!( + "found {} bytes of data in {}", + n, + self.live.path().display() + ); + Ok(n) } } diff --git a/src/run.rs b/src/run.rs deleted file mode 100644 index 94261ff..0000000 --- a/src/run.rs +++ /dev/null @@ -1,3 +0,0 @@ -/// Runtime state for running Obnam benchmarks. -pub struct RuntimeState { -} diff --git a/src/state.rs b/src/state.rs index 152d569..d70af11 100644 --- a/src/state.rs +++ b/src/state.rs @@ -1,8 +1,9 @@ use crate::data::{Data, DataError}; use crate::result::{Measurement, OpMeasurements, Operation}; use crate::step::Step; +use log::{debug, info}; +use std::path::Path; use std::time::Instant; -use std::path::{Path}; use tempfile::{tempdir, TempDir}; /// Runtime state for running Obnam benchmarks. @@ -44,25 +45,31 @@ impl State { } pub fn execute(&mut self, step: &Step) -> Result, StateError> { + debug!("executing step {:?}", step); let now = Instant::now(); let om = match step { Step::Start(name) => { + info!("starting benchmark {}", name); self.current_benchmark = Some(CurrentBenchmark::new(name, self.tempdir.path())?); None } - Step::Stop(_) => { + Step::Stop(name) => { + info!("ending benchmark {}", name); self.current_benchmark = None; None } Step::Create(x) => { + info!("creating {} test data files", x.files); self.current()?.data.create(x)?; None } Step::Rename(x) => { + info!("renaming {} test data files", x.files); self.current()?.data.rename(x)?; None } Step::Delete(x) => { + info!("deleting {} test data files", x.files); self.current()?.data.delete(x)?; None } @@ -70,12 +77,12 @@ impl State { Step::Restore(x) => Some(restore(*x, self.current()?)?), }; - println!("{:?}", step); let t = std::time::Duration::from_millis(10); std::thread::sleep(t); if let Some(mut om) = om { let ms = now.elapsed().as_millis(); + debug!("step duration was {} ms", ms); om.push(Measurement::DurationMs(ms)); Ok(Some(om)) } else { @@ -85,6 +92,7 @@ impl State { } fn backup(i: usize, current: &CurrentBenchmark) -> Result { + info!("backing up generation number {}", i); let mut om = OpMeasurements::new(¤t.name, Operation::Backup(i)); om.push(Measurement::TotalFiles(current.data.file_count()?)); om.push(Measurement::TotalData(current.data.file_size()?)); @@ -92,6 +100,7 @@ fn backup(i: usize, current: &CurrentBenchmark) -> Result Result { + info!("restoring generation number {}", i); Ok(OpMeasurements::new(¤t.name, Operation::Restore(i))) } -- cgit v1.2.1