print delta startup timing with DELTA_DEBUG_TIMING=1 env var

If this env var is set, on exit delta will print how long reading the
config files, setting up the tty, querying the calling process and
painting the first line took, in absolute ms from the start of `main()`.

Note: The process time reports when it was first requested, not when it
finished. This may be much later than the first paint.

E.g. on `git show`:

delta timings (ms after start): tty setup: 2.3 ms, read configs: 6.0 ms, query processes: 26.1 ms, first paint: 10.1

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
+}