From 40fbe9ba35116ccff04251f6c52d1607f3480c6f Mon Sep 17 00:00:00 2001 From: Lars Wirzenius Date: Sat, 2 Apr 2022 15:48:23 +0300 Subject: feat: add data structures for accumulating time measurements Sponsored-by: author --- src/accumulated_time.rs | 79 ++++++++++++++++++++++++++++++++ src/lib.rs | 2 + src/performance.rs | 118 ++++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 199 insertions(+) create mode 100644 src/accumulated_time.rs create mode 100644 src/performance.rs diff --git a/src/accumulated_time.rs b/src/accumulated_time.rs new file mode 100644 index 0000000..e633a10 --- /dev/null +++ b/src/accumulated_time.rs @@ -0,0 +1,79 @@ +//! Measure accumulated time for various operations. + +use std::collections::HashMap; +use std::hash::Hash; +use std::sync::Mutex; +use std::time::Instant; + +/// Accumulated times for different clocks. +/// +/// The caller defines a clock type, usually an enum. +/// `AccumulatedTime` accumulates time for each possible clock. +/// Conceptually, every type of clock exists. If a type of clock +/// doesn't ever get created, it measures at 0 accumulated time. +#[derive(Debug)] +pub struct AccumulatedTime { + accumulated: Mutex>, +} + +#[derive(Debug, Default)] +struct ClockTime { + nanos: u128, + started: Option, +} + +impl AccumulatedTime { + /// Create a new accumulated time collector. + #[allow(clippy::new_without_default)] + pub fn new() -> Self { + Self { + accumulated: Mutex::new(HashMap::new()), + } + } + + /// Start a new clock of a given type to measure a span of time. + /// + /// The clock's measured time is added to the accumulator when the + /// clock is stopped. + pub fn start(&mut self, clock: T) { + let mut map = self.accumulated.lock().unwrap(); + let ct = map.entry(clock).or_insert_with(ClockTime::default); + assert!(ct.started.is_none()); + ct.started = Some(Instant::now()); + } + + /// Stop a running clock. + /// + /// Its run time is added to the accumulated time for that kind of clock. + pub fn stop(&mut self, clock: T) { + let mut map = self.accumulated.lock().unwrap(); + if let Some(mut ct) = map.get_mut(&clock) { + assert!(ct.started.is_some()); + if let Some(started) = ct.started.take() { + ct.nanos += started.elapsed().as_nanos(); + ct.started = None; + } + } + } + + /// Return the accumulated time for a type of clock, as whole seconds. + pub fn secs(&self, clock: T) -> u128 { + self.nanos(clock) / 1_000_000_000u128 + } + + /// Return the accumulated time for a type of clock, as nanoseconds. + /// + /// This includes the time spent in a currently running clock. + pub fn nanos(&self, clock: T) -> u128 { + let map = self.accumulated.lock().unwrap(); + if let Some(ct) = map.get(&clock) { + if let Some(started) = ct.started { + ct.nanos + started.elapsed().as_nanos() + } else { + ct.nanos + } + } else { + 0 + } + } +} diff --git a/src/lib.rs b/src/lib.rs index fdb318f..fd33a4e 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -5,6 +5,7 @@ #![deny(missing_docs)] +pub mod accumulated_time; pub mod backup_progress; pub mod backup_reason; pub mod backup_run; @@ -34,3 +35,4 @@ 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 new file mode 100644 index 0000000..79fa9ab --- /dev/null +++ b/src/performance.rs @@ -0,0 +1,118 @@ +//! Performance measurements from an Obnam run. + +use crate::accumulated_time::AccumulatedTime; +use log::info; + +/// The kinds of clocks we have. +#[derive(Debug, PartialEq, Eq, Hash, Clone, Copy)] +pub enum Clock { + /// The complete runtime of the program. + RunTime, + + /// Time spent downloading previous backup generations. + GenerationDownload, + + /// 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. +#[derive(Debug)] +pub struct Performance { + args: Vec, + time: AccumulatedTime, + live_files: u64, + files_backed_up: u64, + chunks_uploaded: u64, + chunks_reused: u64, +} + +impl Default for Performance { + fn default() -> Self { + Self { + args: std::env::args().collect(), + time: AccumulatedTime::::new(), + live_files: 0, + files_backed_up: 0, + chunks_reused: 0, + chunks_uploaded: 0, + } + } +} + +impl Performance { + /// Log all performance measurements to the log file. + pub fn log(&self) { + info!("Performance measurements for this Obnam run"); + for (i, arg) in self.args.iter().enumerate() { + info!("argv[{}]={:?}", i, arg); + } + info!("Live files found: {}", self.live_files); + 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) + ); + info!( + "Uploading new generation (seconds): {}", + self.time.secs(Clock::GenerationUpload) + ); + info!( + "Complete run time (seconds): {}", + self.time.secs(Clock::RunTime) + ); + } + + /// Start a specific clock. + pub fn start(&mut self, clock: Clock) { + self.time.start(clock) + } + + /// Stop a specific clock. + pub fn stop(&mut self, clock: Clock) { + self.time.stop(clock) + } + + /// Increment number of live files. + pub fn found_live_files(&mut self, n: u64) { + self.live_files += n; + } + + /// Increment number of files backed up this run. + pub fn back_up_file(&mut self) { + self.files_backed_up += 1; + } + + /// Increment number of reused chunks. + pub fn reuse_chunk(&mut self) { + self.chunks_reused += 1; + } + + /// Increment number of uploaded chunks. + pub fn upload_chunk(&mut self) { + self.chunks_uploaded += 1; + } +} -- cgit v1.2.1