feat: add logging

A lot of logging, if the debug level is chosen. But that's how it
should be.

Sponsored-by: author

4 files changed, 48 insertions, 13 deletions

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<Self, DataError> {
         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<u64, DataError> {
+        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<u64, DataError> {
-        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<Option<OpMeasurements>, 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<OpMeasurements, StateError> {
+    info!("backing up generation number {}", i);
     let mut om = OpMeasurements::new(&current.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<OpMeasurements, StateE
 }
 
 fn restore(i: usize, current: &CurrentBenchmark) -> Result<OpMeasurements, StateError> {
+    info!("restoring generation number {}", i);
     Ok(OpMeasurements::new(&current.name, Operation::Restore(i)))
 }