diff --git a/src/delta.rs b/src/delta.rs index 80c5d7a85..807becf08 100644 --- a/src/delta.rs +++ b/src/delta.rs @@ -147,6 +147,9 @@ impl<'a> StateMachine<'a> { where I: BufRead, { + // right after this the next syscall prints the first line: `write(6, "\33[33mcommit ..." )` + utils::timing::measure(utils::timing::Measurement::FirstPaint); + while let Some(Ok(raw_line_bytes)) = lines.next() { self.ingest_line(raw_line_bytes); diff --git a/src/main.rs b/src/main.rs index d8372a9dd..8799851f4 100644 --- a/src/main.rs +++ b/src/main.rs @@ -54,8 +54,11 @@ pub mod errors { pub use anyhow::{anyhow, Context, Error, Result}; } +const DELTA_DEBUG_TIMING: &str = "DELTA_DEBUG_TIMING"; + #[cfg(not(tarpaulin_include))] fn main() -> std::io::Result<()> { + utils::timing::measure(utils::timing::Measurement::Start); // Do this first because both parsing all the input in `run_app()` and // listing all processes takes about 50ms on Linux. // It also improves the chance that the calling process is still around when @@ -79,6 +82,7 @@ pub fn run_app( args: Vec, capture_output: Option<&mut Cursor>>, ) -> std::io::Result { + let _timing_reporter = utils::timing::report_on_exit(); let env = env::DeltaEnv::init(); let assets = utils::bat::assets::load_highlighting_assets(); let opt = cli::Opt::from_args_and_git_config(args, &env, assets); @@ -95,6 +99,8 @@ pub fn run_app( Call::Delta(opt) => opt, }; + utils::timing::measure(utils::timing::Measurement::ReadConfig); + let subcommand_result = if let Some(shell) = opt.generate_completion { Some(subcommands::generate_completion::generate_completion_file( shell, diff --git a/src/options/theme.rs b/src/options/theme.rs index 215f49d3d..377975296 100644 --- a/src/options/theme.rs +++ b/src/options/theme.rs @@ -22,6 +22,7 @@ use terminal_colorsaurus::{color_scheme, QueryOptions}; use crate::cli::{self, DetectDarkLight}; use crate::color::{ColorMode, ColorMode::*}; +use crate::utils; #[allow(non_snake_case)] pub fn set__color_mode__syntax_theme__syntax_set(opt: &mut cli::Opt, assets: HighlightingAssets) { @@ -86,7 +87,7 @@ fn get_color_mode(opt: &cli::Opt) -> Option { } else if opt.dark { Some(Dark) } else if should_detect_color_mode(opt) { - detect_color_mode() + utils::timing::measure_completion(detect_color_mode(), utils::timing::Measurement::Tty) } else { None } diff --git a/src/utils/mod.rs b/src/utils/mod.rs index b460e5af3..647230c64 100644 --- a/src/utils/mod.rs +++ b/src/utils/mod.rs @@ -8,4 +8,5 @@ pub mod regex_replacement; pub mod round_char_boundary; pub mod syntect; pub mod tabs; +pub mod timing; pub mod workarounds; diff --git a/src/utils/process.rs b/src/utils/process.rs index f1e3c665d..64ed876a3 100644 --- a/src/utils/process.rs +++ b/src/utils/process.rs @@ -2,6 +2,7 @@ use std::collections::{HashMap, HashSet}; use std::path::Path; use std::sync::{Arc, Condvar, Mutex, MutexGuard}; +use crate::utils; use lazy_static::lazy_static; use sysinfo::{Pid, PidExt, Process, ProcessExt, ProcessRefreshKind, SystemExt}; @@ -68,11 +69,14 @@ pub fn start_determining_calling_process_in_thread() { pub fn calling_process() -> MutexGuard<'static, CallingProcess> { let (caller_mutex, determine_done) = &**CALLER; - determine_done - .wait_while(caller_mutex.lock().unwrap(), |caller| { - *caller == CallingProcess::Pending - }) - .unwrap() + utils::timing::measure_completion( + determine_done + .wait_while(caller_mutex.lock().unwrap(), |caller| { + *caller == CallingProcess::Pending + }) + .unwrap(), + utils::timing::Measurement::Process, + ) } // The return value is duck-typed to work in place of a MutexGuard when testing. diff --git a/src/utils/timing.rs b/src/utils/timing.rs new file mode 100644 index 000000000..1ef041bb3 --- /dev/null +++ b/src/utils/timing.rs @@ -0,0 +1,80 @@ +use crate::DELTA_DEBUG_TIMING; +use std::cell::RefCell; +use std::convert::TryInto; +use std::time::SystemTime; + +#[derive(Debug)] +pub enum Measurement { + Start = 0, + ReadConfig = 1, + Tty = 2, + // TODO: measure when thread is done, not when process info is requested + Process = 3, + FirstPaint = 4, + _Len = 5, +} + +thread_local! { + static DATAPOINTS: RefCell<[u64; Measurement::_Len as usize]> = const { RefCell::new([0; Measurement::_Len as usize]) }; +} + +pub struct TimingReporter; + +impl Drop for TimingReporter { + fn drop(&mut self) { + DATAPOINTS.with(|data| { + let values = data.take(); + if values[0] != 0 { + // TODO: report 0 values as "never required" + eprintln!( + "\n delta timings (ms after start): \ + tty setup: {:.1} ms, read configs: {:.1} ms, query processes: {:.1} ms, first paint: {:.1}", + values[Measurement::Tty as usize] as f32 / 1_000., + values[Measurement::ReadConfig as usize] as f32 / 1_000., + values[Measurement::Process as usize] as f32 / 1_000., + values[Measurement::FirstPaint as usize] as f32 / 1_000., + ); + } + }) + } +} + +// After calling with `Start`, collect timestamps relative to this recorded start time. Must be +// called in the main thread (uses Thread Local Storage to avoid `Arc`s etc.) +pub fn measure(what: Measurement) { + let now = SystemTime::now() + .duration_since(SystemTime::UNIX_EPOCH) + .unwrap_or_default(); + // u128 as u64, microseconds are small enough for simple subtraction + let usecs: u64 = now.as_micros().try_into().unwrap_or_default(); + use Measurement::*; + match what { + Start => { + if std::env::var_os(DELTA_DEBUG_TIMING).is_some() { + DATAPOINTS.with(|data| { + let mut initial = data.take(); + initial[Start as usize] = usecs; + data.replace(initial) + }); + } + } + ReadConfig | Tty | Process | FirstPaint => DATAPOINTS.with(|data| { + let mut values = data.take(); + if values[0] == 0 { + return; + } + values[what as usize] = usecs.saturating_sub(values[0]); + data.replace(values); + }), + _Len => unreachable!(), + } +} + +pub fn measure_completion(x: T, what: Measurement) -> T { + measure(what); + x +} + +pub fn report_on_exit() -> TimingReporter { + TimingReporter +}