diff --git a/Cargo.lock b/Cargo.lock index e037758..85fa818 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2,6 +2,12 @@ # It is not intended for manual editing. version = 3 +[[package]] +name = "adler" +version = "1.0.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f26201604c87b1e01bd3d98f8d5d9a8fcbb815e8cedb41ffccbeb4bf593a35fe" + [[package]] name = "ansi_term" version = "0.12.1" @@ -28,12 +34,24 @@ version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cdb031dd78e28731d87d56cc8ffef4a8f36ca26c38fe2de700543e627f8a464a" +[[package]] +name = "base64" +version = "0.13.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9e1b586273c5702936fe7b7d6896644d8be71e6314cfe09d3167c95f712589e8" + [[package]] name = "bitflags" version = "1.3.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "bef38d45163c2f1dde094a7dfd33ccf595c92905c8f8f4fdc18d06fb1037718a" +[[package]] +name = "byteorder" +version = "1.4.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "14c189c53d098945499cdfa7ecc63567cf3886b3332b312a5b4585d8d3a6a610" + [[package]] name = "bytes" version = "1.1.0" @@ -84,6 +102,34 @@ dependencies = [ "textwrap", ] +[[package]] +name = "crc32fast" +version = "1.3.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b540bd8bc810d3885c6ea91e2018302f68baba2129ab3e88f32389ee9370880d" +dependencies = [ + "cfg-if", +] + +[[package]] +name = "crossbeam-channel" +version = "0.5.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c2dd04ddaf88237dc3b8d8f9a3c1004b506b54b3313403944054d23c0870c521" +dependencies = [ + "cfg-if", + "crossbeam-utils", +] + +[[package]] +name = "crossbeam-utils" +version = "0.8.12" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "edbafec5fa1f196ca66527c1b12c2ec4745ca14b50f1ad8f9f6f720b55d11fac" +dependencies = [ + "cfg-if", +] + [[package]] name = "dirs" version = "4.0.0" @@ -106,12 +152,13 @@ dependencies = [ [[package]] name = "dura" -version = "0.2.0-snapshot" +version = "0.2.0" dependencies = [ "chrono", "clap", "dirs", "git2", + "hdrhistogram", "serde", "serde_json", "serial_test", @@ -131,6 +178,16 @@ dependencies = [ "instant", ] +[[package]] +name = "flate2" +version = "1.0.24" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f82b0f4c27ad9f8bfd1f3208d882da2b09c301bc1c828fd3a00d0216d2fbbff6" +dependencies = [ + "crc32fast", + "miniz_oxide", +] + [[package]] name = "form_urlencoded" version = "1.0.1" @@ -173,6 +230,20 @@ version = "0.11.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ab5ef0d4909ef3724cc8cce6ccc8572c5c817592e9285f5464f8e86f8bd3726e" +[[package]] +name = "hdrhistogram" +version = "7.5.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7f19b9f54f7c7f55e31401bb647626ce0cf0f67b0004982ce815b3ee72a02aa8" +dependencies = [ + "base64", + "byteorder", + "crossbeam-channel", + "flate2", + "nom", + "num-traits", +] + [[package]] name = "hermit-abi" version = "0.1.19" @@ -318,6 +389,21 @@ version = "2.4.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "308cc39be01b73d0d18f82a0e7b2a3df85245f84af96fdddc5d202d27e47b86a" +[[package]] +name = "minimal-lexical" +version = "0.2.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "68354c5c6bd36d73ff3feceb05efa59b6acb7626617f4962be322a825e61f79a" + +[[package]] +name = "miniz_oxide" +version = "0.5.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "96590ba8f175222643a85693f33d26e9c8a015f599c216509b1a6894af675d34" +dependencies = [ + "adler", +] + [[package]] name = "mio" version = "0.7.14" @@ -340,6 +426,16 @@ dependencies = [ "winapi", ] +[[package]] +name = "nom" +version = "7.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a8903e5a29a317527874d0402f867152a3d21c908bb0b933e416c65e301d4c36" +dependencies = [ + "memchr", + "minimal-lexical", +] + [[package]] name = "ntapi" version = "0.3.6" diff --git a/Cargo.toml b/Cargo.toml index 4622f75..eeaaaac 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "dura" -version = "0.2.0" +version = "0.2.0-dev" edition = "2021" authors = ["Tim Kellogg and the Internet"] description = "Dura backs up your work automatically via Git commits." @@ -20,6 +20,7 @@ chrono = "0.4" toml = "0.5.8" tracing = { version = "0.1.5"} tracing-subscriber = { version = "0.3", features = ["env-filter", "registry"] } +hdrhistogram = "7.5.2" [dev-dependencies] tempfile = "3.2.0" diff --git a/src/config.rs b/src/config.rs index 833f92b..3be9523 100644 --- a/src/config.rs +++ b/src/config.rs @@ -11,7 +11,7 @@ use crate::git_repo_iter::GitRepoIter; type Result = std::result::Result>; -#[derive(Debug, Serialize, Deserialize, PartialEq, Clone)] +#[derive(Debug, Serialize, Deserialize, PartialEq, Eq, Clone)] pub struct WatchConfig { pub include: Vec, pub exclude: Vec, @@ -34,7 +34,7 @@ impl Default for WatchConfig { } } -#[derive(Debug, Serialize, Deserialize, PartialEq)] +#[derive(Debug, Serialize, Deserialize, PartialEq, Eq)] pub struct Config { // When commit_exclude_git_config is true, // never use any git configuration to sign dura's commits. diff --git a/src/database.rs b/src/database.rs index ca44cfa..89ef182 100644 --- a/src/database.rs +++ b/src/database.rs @@ -5,7 +5,7 @@ use std::{env, fs, io}; use serde::{Deserialize, Serialize}; -#[derive(Debug, Serialize, Deserialize, PartialEq)] +#[derive(Debug, Serialize, Deserialize, PartialEq, Eq)] pub struct RuntimeLock { pub pid: Option, } diff --git a/src/log.rs b/src/log.rs index 7c191e2..601573d 100644 --- a/src/log.rs +++ b/src/log.rs @@ -1,7 +1,11 @@ use std::fmt::Debug; +use std::time::{Duration, Instant}; -use crate::snapshots::CaptureStatus; +use hdrhistogram::Histogram; use serde::{Deserialize, Serialize}; +use tracing::trace; + +use crate::snapshots::CaptureStatus; #[derive(Debug, Serialize, Deserialize)] pub enum Operation { @@ -11,6 +15,10 @@ pub enum Operation { error: Option, latency: f32, }, + CollectStats { + per_dir_stats: Histo, + loop_stats: Histo, + }, } impl Operation { @@ -22,6 +30,134 @@ impl Operation { error, latency: _, } => op.is_some() || error.is_some(), + Operation::CollectStats { .. } => { + true // logic punted to StatCollector + } + } + } + + pub fn log_str(&mut self) -> String { + // This unwrap seems safe, afaict. We're not cramming any user supplied strings in here. + serde_json::to_string(self).expect("Couldn't serialize to JSON") + } +} + +#[derive(Debug, Serialize, Deserialize)] +struct Stats { + dir_stats: Histo, + loop_stats: Histo, +} + +/// A serializable form of a hdrhistogram, mainly just for logging out +/// in a way we want to read it +#[derive(Debug, Serialize, Deserialize)] +pub struct Histo { + mean: f64, + count: u64, + min: u64, + max: u64, + percentiles: Vec, +} + +/// For serializing to JSON +/// +/// Choice of tiny names because this one shows up a lot, one +/// for each percentile bucket. It shows a lot more data +/// points at the upper percentiles, so we need to capture +/// both percentile and associated millisecond value. +#[derive(Debug, Serialize, Deserialize)] +pub struct Percentile { + pct: f64, + val: u64, +} + +impl Histo { + pub fn from_histogram(hist: &Histogram) -> Histo { + Self { + mean: hist.mean(), + count: hist.len(), + min: hist.min(), + max: hist.max(), + percentiles: hist + .iter_quantiles(2) + .map(|q| Percentile { + pct: q.percentile(), + val: q.value_iterated_to(), + }) + .collect(), + } + } +} + +#[derive(Debug)] +pub struct StatCollector { + start: Instant, + per_dir_stats: Histogram, + loop_stats: Histogram, +} + +/// 5 minutes in milliseconds +const MAX_LATENCY_IMAGINABLE: u64 = 5 * 60 * 1000; + +/// How many seconds between logging stats? +const STAT_LOG_INTERVAL: f32 = 600.0; + +impl StatCollector { + pub fn new() -> Self { + Self { + start: Instant::now(), + per_dir_stats: Histogram::::new_with_max(MAX_LATENCY_IMAGINABLE, 3).unwrap(), + loop_stats: Histogram::::new_with_max(MAX_LATENCY_IMAGINABLE, 3).unwrap(), } } + + pub fn to_op(&self) -> Operation { + Operation::CollectStats { + per_dir_stats: Histo::from_histogram(&self.per_dir_stats), + loop_stats: Histo::from_histogram(&self.loop_stats), + } + } + + pub fn should_log(&self) -> bool { + let elapsed = (Instant::now() - self.start).as_secs_f32(); + trace!( + elapsed = elapsed, + target = STAT_LOG_INTERVAL, + "Should we log metrics?" + ); + elapsed > STAT_LOG_INTERVAL + } + + pub fn log_str(&mut self) -> String { + let mut op = self.to_op(); + let ret = op.log_str(); + self.reset(); + ret + } + + fn reset(&mut self) { + self.start = Instant::now(); + self.per_dir_stats.clear(); + self.loop_stats.clear(); + } + + /// Record the time it takes to process a single directory. Mainly interested to see if + /// there's any outliers, the histogram should be interesting. + pub fn record_dir(&mut self, latency: Duration) { + let value = latency.as_millis().try_into().unwrap(); + self.per_dir_stats.saturating_record(value); + } + + /// Record the time it takes to go through all directories. I expect mean will be the + /// most interesting datum. Mainly for projecting CPU usage. + pub fn record_loop(&mut self, latency: Duration) { + let value = latency.as_millis().try_into().unwrap(); + self.loop_stats.saturating_record(value); + } +} + +impl Default for StatCollector { + fn default() -> Self { + Self::new() + } } diff --git a/src/poller.rs b/src/poller.rs index 740a3bc..ce6c868 100644 --- a/src/poller.rs +++ b/src/poller.rs @@ -7,7 +7,7 @@ use tracing::{error, info}; use crate::config::Config; use crate::database::RuntimeLock; -use crate::log::Operation; +use crate::log::{Operation, StatCollector}; use crate::snapshots; /// If the directory is a repo, attempts to create a snapshot. @@ -31,19 +31,19 @@ fn process_directory(current_path: &Path) { .to_str() .unwrap_or("") .to_string(); - let operation = Operation::Snapshot { + let mut operation = Operation::Snapshot { repo, op, error, latency, }; if operation.should_log() { - info!(operation = %serde_json::to_string(&operation).unwrap(),"info_operation") + info!(operation = operation.log_str().as_str(), "info_operation") } } #[tracing::instrument] -fn do_task() { +fn do_task(stats: &mut StatCollector) { let runtime_lock = RuntimeLock::load(); if runtime_lock.pid != Some(process::id()) { error!( @@ -55,8 +55,16 @@ fn do_task() { let config = Config::load(); + let loop_start = Instant::now(); for repo in config.git_repos() { + let dir_start = Instant::now(); process_directory(repo.as_path()); + stats.record_dir(Instant::now() - dir_start); + } + stats.record_loop(Instant::now() - loop_start); + + if stats.should_log() { + info!(operation = stats.log_str().as_str(), "poller_stats"); } } @@ -66,8 +74,9 @@ pub async fn start() { runtime_lock.save(); info!(pid = std::process::id()); + let mut stats = StatCollector::new(); loop { time::sleep(time::Duration::from_secs(5)).await; - do_task(); + do_task(&mut stats); } }