From dd13fde5ea8bd61b6b5c7f024df6733301864456 Mon Sep 17 00:00:00 2001 From: Lars Wirzenius Date: Sat, 2 Apr 2022 15:54:02 +0300 Subject: feat: collect and log some time metrics Log the complete run-time of the program, and the time spent downloading the previous generation, and uploading the new generation. Sponsored-by: author --- src/backup_run.rs | 7 +++++++ src/bin/obnam.rs | 11 ++++++++--- src/cmd/backup.rs | 23 ++++++++++++++++------- src/lib.rs | 2 +- src/performance.rs | 21 --------------------- 5 files changed, 32 insertions(+), 32 deletions(-) (limited to 'src') diff --git a/src/backup_run.rs b/src/backup_run.rs index 21140ba..29e82fc 100644 --- a/src/backup_run.rs +++ b/src/backup_run.rs @@ -15,6 +15,7 @@ use crate::fsiter::{AnnotatedFsEntry, FsIterError, FsIterator}; use crate::generation::{ GenId, LocalGeneration, LocalGenerationError, NascentError, NascentGeneration, }; +use crate::performance::{Clock, Performance}; use crate::policy::BackupPolicy; use crate::schema::SchemaVersion; @@ -129,6 +130,7 @@ impl<'a> BackupRun<'a> { &mut self, genid: Option<&GenId>, oldname: &Path, + perf: &mut Performance, ) -> Result { match genid { None => { @@ -140,7 +142,9 @@ impl<'a> BackupRun<'a> { Ok(LocalGeneration::open(oldname)?) } Some(genid) => { + perf.start(Clock::GenerationDownload); let old = self.fetch_previous_generation(genid, oldname).await?; + perf.stop(Clock::GenerationDownload); let progress = BackupProgress::incremental(); progress.files_in_previous_generation(old.file_count()? as u64); @@ -176,6 +180,7 @@ impl<'a> BackupRun<'a> { old: &LocalGeneration, newpath: &Path, schema: SchemaVersion, + perf: &mut Performance, ) -> Result { let mut warnings: Vec = vec![]; let mut new_cachedir_tags = vec![]; @@ -204,7 +209,9 @@ impl<'a> BackupRun<'a> { count }; self.finish(); + perf.start(Clock::GenerationUpload); let gen_id = self.upload_nascent_generation(newpath).await?; + perf.stop(Clock::GenerationUpload); let gen_id = GenId::from_chunk_id(gen_id); Ok(RootsBackupOutcome { files_count, diff --git a/src/bin/obnam.rs b/src/bin/obnam.rs index 15c7d06..089a7a1 100644 --- a/src/bin/obnam.rs +++ b/src/bin/obnam.rs @@ -17,6 +17,7 @@ use obnam::cmd::restore::Restore; use obnam::cmd::show_config::ShowConfig; use obnam::cmd::show_gen::ShowGeneration; use obnam::config::ClientConfig; +use obnam::performance::{Clock, Performance}; use std::path::{Path, PathBuf}; use structopt::StructOpt; @@ -25,14 +26,18 @@ const ORG: &str = ""; const APPLICATION: &str = "obnam"; fn main() { - if let Err(err) = main_program() { + let mut perf = Performance::default(); + perf.start(Clock::RunTime); + if let Err(err) = main_program(&mut perf) { error!("{}", err); eprintln!("ERROR: {}", err); std::process::exit(1); } + perf.stop(Clock::RunTime); + perf.log(); } -fn main_program() -> anyhow::Result<()> { +fn main_program(perf: &mut Performance) -> anyhow::Result<()> { let opt = Opt::from_args(); let config = ClientConfig::read(&config_filename(&opt))?; setup_logging(&config.log)?; @@ -44,7 +49,7 @@ fn main_program() -> anyhow::Result<()> { match opt.cmd { Command::Init(x) => x.run(&config), Command::ListBackupVersions(x) => x.run(&config), - Command::Backup(x) => x.run(&config), + Command::Backup(x) => x.run(&config, perf), Command::Inspect(x) => x.run(&config), Command::Chunkify(x) => x.run(&config), Command::List(x) => x.run(&config), diff --git a/src/cmd/backup.rs b/src/cmd/backup.rs index 7e772b1..8a85703 100644 --- a/src/cmd/backup.rs +++ b/src/cmd/backup.rs @@ -7,6 +7,7 @@ use crate::config::ClientConfig; use crate::dbgen::{schema_version, FileId, DEFAULT_SCHEMA_MAJOR}; use crate::error::ObnamError; use crate::generation::GenId; +use crate::performance::{Clock, Performance}; use crate::schema::VersionComponent; use log::info; @@ -25,12 +26,16 @@ pub struct Backup { impl Backup { /// Run the command. - pub fn run(&self, config: &ClientConfig) -> Result<(), ObnamError> { + pub fn run(&self, config: &ClientConfig, perf: &mut Performance) -> Result<(), ObnamError> { let rt = Runtime::new()?; - rt.block_on(self.run_async(config)) + rt.block_on(self.run_async(config, perf)) } - async fn run_async(&self, config: &ClientConfig) -> Result<(), ObnamError> { + async fn run_async( + &self, + config: &ClientConfig, + perf: &mut Performance, + ) -> Result<(), ObnamError> { let runtime = SystemTime::now(); let major = self.backup_version.or(Some(DEFAULT_SCHEMA_MAJOR)).unwrap(); @@ -52,28 +57,32 @@ impl Backup { Err(_) => { info!("fresh backup without a previous generation"); let mut run = BackupRun::initial(config, &client)?; - let old = run.start(None, &oldtemp).await?; + let old = run.start(None, &oldtemp, perf).await?; ( false, - run.backup_roots(config, &old, &newtemp, schema).await?, + run.backup_roots(config, &old, &newtemp, schema, perf) + .await?, ) } Ok(old_id) => { info!("incremental backup based on {}", old_id); let mut run = BackupRun::incremental(config, &client)?; - let old = run.start(Some(&old_id), &oldtemp).await?; + let old = run.start(Some(&old_id), &oldtemp, perf).await?; ( true, - run.backup_roots(config, &old, &newtemp, schema).await?, + run.backup_roots(config, &old, &newtemp, schema, perf) + .await?, ) } }; + perf.start(Clock::GenerationUpload); let mut trust = trust; trust.append_backup(outcome.gen_id.as_chunk_id()); trust.finalize(current_timestamp()); let trust = trust.to_data_chunk()?; let trust_id = client.upload_chunk(trust).await?; + perf.stop(Clock::GenerationUpload); info!("uploaded new client-trust {}", trust_id); for w in outcome.warnings.iter() { diff --git a/src/lib.rs b/src/lib.rs index fd33a4e..a0a53c7 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -30,9 +30,9 @@ pub mod genmeta; pub mod index; pub mod indexedstore; pub mod passwords; +pub mod performance; pub mod policy; pub mod schema; pub mod server; pub mod store; pub mod workqueue; -pub mod performance; diff --git a/src/performance.rs b/src/performance.rs index 79fa9ab..29c2328 100644 --- a/src/performance.rs +++ b/src/performance.rs @@ -14,15 +14,6 @@ pub enum Clock { /// Time spent uploading backup generations. GenerationUpload, - - /// Time spent checking if a chunk exists already on server. - HasChunk, - - /// Time spent computing splitting files into chunks. - Chunking, - - /// Time spent scanning live data. - Scanning, } /// Collected measurements from this Obnam run. @@ -60,18 +51,6 @@ impl Performance { info!("Files backed up: {}", self.files_backed_up); info!("Chunks uploaded: {}", self.chunks_uploaded); info!("Chunks reused: {}", self.chunks_reused); - info!( - "Scanning live data (seconds): {}", - self.time.secs(Clock::Scanning) - ); - info!( - "Chunking live data (seconds): {}", - self.time.secs(Clock::Chunking) - ); - info!( - "Checking for duplicate chunks (seconds): {}", - self.time.secs(Clock::HasChunk) - ); info!( "Downloading previous generation (seconds): {}", self.time.secs(Clock::GenerationDownload) -- cgit v1.2.1