print delta startup timing with DELTA_DEBUG_TIMING=1 env var

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);
 

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<OsString>,
     capture_output: Option<&mut Cursor<Vec<u8>>>,
 ) -> std::io::Result<i32> {
+    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,

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<ColorMode> {
     } 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
     }

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;

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.

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<T>(x: T, what: Measurement) -> T {
+    measure(what);
+    x
+}
+
+pub fn report_on_exit() -> TimingReporter {
+    TimingReporter
+}