add performance metrics for measuring startup time (#3854)

* add performance metrics for measureing startup time

* removed some comments

* update so tests pass

* update default.toml for tests, merged main

* fix clippy lints

* wording changes

Cargo.lock

@@ -3055,6 +3055,7 @@ version = "0.34.1"
 dependencies = [
  "ctrlc",
  "indexmap",
+ "lazy_static 1.4.0",
  "log",
  "nu-ansi-term",
  "nu-command",

crates/nu-cli/Cargo.toml

@@ -31,6 +31,7 @@ ctrlc = { version="3.1.7", optional=true }
 shadow-rs = { version="0.6", default-features=false, optional=true }
 serde = { version="1.0.123", features=["derive"] }
 serde_yaml = "0.8.16"
+lazy_static = "1.4.0"
 
 [build-dependencies]
 shadow-rs = "0.6"

crates/nu-cli/src/app.rs

@@ -1,10 +1,10 @@
 mod logger;
 mod options;
 mod options_parser;
+pub mod stopwatch;
 
-pub use options::{CliOptions, NuScript, Options};
+use self::stopwatch::Stopwatch;
-use options_parser::{NuParser, OptionsParser};
+use lazy_static::lazy_static;
-
 use nu_command::{commands::NuSignature as Nu, utils::test_bins as binaries};
 use nu_engine::{get_full_help, EvaluationContext};
 use nu_errors::ShellError;
@@ -12,6 +12,18 @@ use nu_protocol::hir::{Call, Expression, SpannedExpression, Synthetic};
 use nu_protocol::{Primitive, UntaggedValue};
 use nu_source::{Span, Tag};
 use nu_stream::InputStream;
+pub use options::{CliOptions, NuScript, Options};
+use options_parser::{NuParser, OptionsParser};
+use std::sync::Mutex;
+
+lazy_static! {
+    pub static ref STOPWATCH: Mutex<Stopwatch> = {
+        let mut sw = Stopwatch::default();
+        sw.start();
+        sw.stop();
+        Mutex::new(sw)
+    };
+}
 
 pub struct App {
     parser: Box<dyn OptionsParser>,
@@ -32,6 +44,14 @@ impl App {
     }
 
     pub fn main(&self, argv: &[String]) -> Result<(), ShellError> {
+        if self.perf() {
+            // start the stopwatch running
+            STOPWATCH
+                .lock()
+                .expect("unable to lock the stopwatch")
+                .start();
+        }
+
         let argv = quote_positionals(argv).join(" ");
 
         if let Err(cause) = self.parse(&argv) {
@@ -52,6 +72,21 @@ impl App {
 
             consume(context, stream)?;
 
+            if self.perf() {
+                // stop the stopwatch since we're exiting
+                STOPWATCH
+                    .lock()
+                    .expect("unable to lock the stopwatch")
+                    .stop();
+                eprintln!(
+                    "help {:?}",
+                    STOPWATCH
+                        .lock()
+                        .expect("unable to lock the stopwatch")
+                        .elapsed()
+                );
+            }
+
             std::process::exit(0);
         }
 
@@ -93,6 +128,22 @@ impl App {
             };
 
             consume(context, stream)?;
+
+            if self.perf() {
+                // stop the stopwatch since we're exiting
+                STOPWATCH
+                    .lock()
+                    .expect("unable to lock the stopwatch")
+                    .stop();
+                eprintln!(
+                    "version {:?}",
+                    STOPWATCH
+                        .lock()
+                        .expect("unable to lock the stopwatch")
+                        .elapsed()
+                );
+            }
+
             std::process::exit(0);
         }
 
@@ -113,10 +164,10 @@ impl App {
         }
 
         let mut opts = CliOptions::new();
-
         opts.config = self.config().map(std::ffi::OsString::from);
         opts.stdin = self.takes_stdin();
         opts.save_history = self.save_history();
+        opts.perf = self.perf();
 
         use logger::{configure, debug_filters, logger, trace_filters};
 
@@ -128,6 +179,14 @@ impl App {
             Ok(())
         })?;
 
+        if self.perf() {
+            // start a new split
+            STOPWATCH
+                .lock()
+                .expect("unable to lock the stopwatch")
+                .start()
+        }
+
         if let Some(commands) = self.commands() {
             let commands = commands?;
             let script = NuScript::code(&commands)?;
@@ -136,6 +195,21 @@ impl App {
             return crate::run_script_file(context, opts);
         }
 
+        if self.perf() {
+            // start a new spit
+            eprintln!(
+                "commands using -c at launch: {:?}",
+                STOPWATCH
+                    .lock()
+                    .expect("unable to lock the stopwatch")
+                    .elapsed_split()
+            );
+            STOPWATCH
+                .lock()
+                .expect("unable to lock the stopwatch")
+                .start();
+        }
+
         if let Some(scripts) = self.scripts() {
             let mut source_files = vec![];
             for script in scripts {
@@ -162,12 +236,38 @@ impl App {
             return Ok(());
         }
 
+        if self.perf() {
+            // start a new split
+            eprintln!(
+                "script file(s) passed in: {:?}",
+                STOPWATCH
+                    .lock()
+                    .expect("unable to lock the stopwatch")
+                    .elapsed_split()
+            );
+            STOPWATCH
+                .lock()
+                .expect("unable to lock the stopwatch")
+                .start();
+        }
+
         let context = crate::create_default_context(true)?;
 
         if !self.skip_plugins() {
             let _ = crate::register_plugins(&context);
         }
 
+        if self.perf() {
+            // start a new split
+            eprintln!(
+                "plugins registered: {:?}",
+                STOPWATCH
+                    .lock()
+                    .expect("unable to lock the stopwatch")
+                    .elapsed_split()
+            );
+        }
+
         #[cfg(feature = "rustyline-support")]
         {
             crate::cli(context, opts)?;
@@ -189,6 +289,13 @@ impl App {
         })
     }
 
+    pub fn perf(&self) -> bool {
+        self.options
+            .get("perf")
+            .map(|v| matches!(v.as_bool(), Ok(true)))
+            .unwrap_or(false)
+    }
+
     pub fn help(&self) -> bool {
         self.options
             .get("help")

crates/nu-cli/src/app/options.rs

@@ -10,6 +10,7 @@ pub struct CliOptions {
     pub stdin: bool,
     pub scripts: Vec<NuScript>,
     pub save_history: bool,
+    pub perf: bool,
 }
 
 impl Default for CliOptions {
@@ -25,6 +26,7 @@ impl CliOptions {
             stdin: false,
             scripts: vec![],
             save_history: true,
+            perf: false,
         }
     }
 }

crates/nu-cli/src/app/stopwatch.rs

@@ -0,0 +1,118 @@
+#![allow(dead_code)]
+use std::default::Default;
+use std::fmt;
+use std::time::{Duration, Instant};
+
+#[derive(Clone, Copy)]
+pub struct Stopwatch {
+    /// The time the stopwatch was started last, if ever.
+    start_time: Option<Instant>,
+    /// The time the stopwatch was split last, if ever.
+    split_time: Option<Instant>,
+    /// The time elapsed while the stopwatch was running (between start() and stop()).
+    elapsed: Duration,
+}
+
+impl Default for Stopwatch {
+    fn default() -> Stopwatch {
+        Stopwatch {
+            start_time: None,
+            split_time: None,
+            elapsed: Duration::from_secs(0),
+        }
+    }
+}
+
+impl fmt::Display for Stopwatch {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        return write!(f, "{}ms", self.elapsed_ms());
+    }
+}
+
+impl Stopwatch {
+    /// Returns a new stopwatch.
+    pub fn new() -> Stopwatch {
+        let sw: Stopwatch = Default::default();
+        sw
+    }
+
+    /// Returns a new stopwatch which will immediately be started.
+    pub fn start_new() -> Stopwatch {
+        let mut sw = Stopwatch::new();
+        sw.start();
+        sw
+    }
+
+    /// Starts the stopwatch.
+    pub fn start(&mut self) {
+        self.start_time = Some(Instant::now());
+    }
+
+    /// Stops the stopwatch.
+    pub fn stop(&mut self) {
+        self.elapsed = self.elapsed();
+        self.start_time = None;
+        self.split_time = None;
+    }
+
+    /// Resets all counters and stops the stopwatch.
+    pub fn reset(&mut self) {
+        self.elapsed = Duration::from_secs(0);
+        self.start_time = None;
+        self.split_time = None;
+    }
+
+    /// Resets and starts the stopwatch again.
+    pub fn restart(&mut self) {
+        self.reset();
+        self.start();
+    }
+
+    /// Returns whether the stopwatch is running.
+    pub fn is_running(&self) -> bool {
+        self.start_time.is_some()
+    }
+
+    /// Returns the elapsed time since the start of the stopwatch.
+    pub fn elapsed(&self) -> Duration {
+        match self.start_time {
+            // stopwatch is running
+            Some(t1) => t1.elapsed() + self.elapsed,
+            // stopwatch is not running
+            None => self.elapsed,
+        }
+    }
+
+    /// Returns the elapsed time since the start of the stopwatch in milliseconds.
+    pub fn elapsed_ms(&self) -> i64 {
+        let dur = self.elapsed();
+        (dur.as_secs() * 1000 + dur.subsec_millis() as u64) as i64
+    }
+
+    /// Returns the elapsed time since last split or start/restart.
+    ///
+    /// If the stopwatch is in stopped state this will always return a zero Duration.
+    pub fn elapsed_split(&mut self) -> Duration {
+        match self.start_time {
+            // stopwatch is running
+            Some(start) => {
+                let res = match self.split_time {
+                    Some(split) => split.elapsed(),
+                    None => start.elapsed(),
+                };
+                self.split_time = Some(Instant::now());
+                res
+            }
+            // stopwatch is not running
+            None => Duration::from_secs(0),
+        }
+    }
+
+    /// Returns the elapsed time since last split or start/restart in milliseconds.
+    ///
+    /// If the stopwatch is in stopped state this will always return zero.
+    pub fn elapsed_split_ms(&mut self) -> i64 {
+        let dur = self.elapsed_split();
+        (dur.as_secs() * 1000 + dur.subsec_millis() as u64) as i64
+    }
+}

crates/nu-cli/src/cli.rs

@@ -1,3 +1,4 @@
+use crate::app::STOPWATCH;
 use crate::line_editor::configure_ctrl_c;
 use nu_ansi_term::Color;
 use nu_engine::{maybe_print_errors, run_block, script::run_script_standalone, EvaluationContext};
@@ -97,15 +98,26 @@ pub fn cli(
     } else {
         load_global_cfg(&context);
     }
+
     // Store cmd duration in an env var
     context.scope.add_env_var(
         "CMD_DURATION_MS",
         format!("{}", startup_commands_start_time.elapsed().as_millis()),
     );
-    trace!(
+
-        "startup commands took {:?}",
+    if options.perf {
-        startup_commands_start_time.elapsed()
+        eprintln!(
+            "config loaded: {:?}",
+            STOPWATCH
+                .lock()
+                .expect("unable to lock the stopwatch")
+                .elapsed_split()
         );
+        STOPWATCH
+            .lock()
+            .expect("unable to lock the stopwatch")
+            .start();
+    }
 
     //Configure rustyline
     let mut rl = default_rustyline_editor_configuration();
@@ -118,11 +130,39 @@ pub fn cli(
         nu_data::config::path::default_history_path()
     };
 
+    if options.perf {
+        eprintln!(
+            "rustyline configuration: {:?}",
+            STOPWATCH
+                .lock()
+                .expect("unable to lock the stopwatch")
+                .elapsed_split()
+        );
+        STOPWATCH
+            .lock()
+            .expect("unable to lock the stopwatch")
+            .start();
+    }
+
     // Don't load history if it's not necessary
     if options.save_history {
         let _ = rl.load_history(&history_path);
     }
 
+    if options.perf {
+        eprintln!(
+            "history load: {:?}",
+            STOPWATCH
+                .lock()
+                .expect("unable to lock the stopwatch")
+                .elapsed_split()
+        );
+        STOPWATCH
+            .lock()
+            .expect("unable to lock the stopwatch")
+            .start();
+    }
+
     //set vars from cfg if present
     let (skip_welcome_message, prompt) = if let Some(cfg) = &context.configs().lock().global_config
     {
@@ -136,6 +176,20 @@ pub fn cli(
         (false, None)
     };
 
+    if options.perf {
+        eprintln!(
+            "load custom prompt: {:?}",
+            STOPWATCH
+                .lock()
+                .expect("unable to lock the stopwatch")
+                .elapsed_split()
+        );
+        STOPWATCH
+            .lock()
+            .expect("unable to lock the stopwatch")
+            .start();
+    }
+
     //Check whether dir we start in contains local cfg file and if so load it.
     load_local_cfg_if_present(&context);
 
@@ -159,6 +213,20 @@ pub fn cli(
 
     let mut ctrlcbreak = false;
 
+    if options.perf {
+        eprintln!(
+            "timing stopped. starting run loop: {:?}",
+            STOPWATCH
+                .lock()
+                .expect("unable to lock the stopwatch")
+                .elapsed_split()
+        );
+        STOPWATCH
+            .lock()
+            .expect("unable to lock the stopwatch")
+            .stop();
+    }
+
     loop {
         if context.ctrl_c().load(Ordering::SeqCst) {
             context.ctrl_c().store(false, Ordering::SeqCst);

crates/nu-command/src/commands/core_commands/nu_signature.rs

@@ -14,6 +14,7 @@ impl WholeStreamCommand for Command {
             .switch("stdin", "redirect stdin", None)
             .switch("skip-plugins", "do not load plugins", None)
             .switch("no-history", "don't save history", None)
+            .switch("perf", "show startup performance metrics", None)
             .named(
                 "commands",
                 SyntaxShape::String,

crates/nu-test-support/src/playground/director.rs

@@ -67,6 +67,7 @@ impl Director {
                 config_file.to_str().expect("failed to convert."),
             ]);
         }
+        process.arg("--perf");
 
         director.executable = Some(process);
         director

tests/fixtures/playground/config/default.toml

@@ -1 +1,3 @@
 skip_welcome_message = true
+filesize_format = "auto"
+rm_always_trash = false