From 23ba01d89c0644686bdf1ad9cd952ee123d9ebc5 Mon Sep 17 00:00:00 2001 From: Darren Schroeder <343840+fdncred@users.noreply.github.com> Date: Thu, 29 Jul 2021 18:52:40 -0500 Subject: [PATCH] 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 | 1 + crates/nu-cli/Cargo.toml | 1 + crates/nu-cli/src/app.rs | 115 ++++++++++++++++- crates/nu-cli/src/app/options.rs | 2 + crates/nu-cli/src/app/stopwatch.rs | 118 ++++++++++++++++++ crates/nu-cli/src/cli.rs | 76 ++++++++++- .../commands/core_commands/nu_signature.rs | 1 + .../src/playground/director.rs | 1 + tests/fixtures/playground/config/default.toml | 2 + 9 files changed, 309 insertions(+), 8 deletions(-) create mode 100644 crates/nu-cli/src/app/stopwatch.rs diff --git a/Cargo.lock b/Cargo.lock index ec425c0fe4..954a40fe4e 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3055,6 +3055,7 @@ version = "0.34.1" dependencies = [ "ctrlc", "indexmap", + "lazy_static 1.4.0", "log", "nu-ansi-term", "nu-command", diff --git a/crates/nu-cli/Cargo.toml b/crates/nu-cli/Cargo.toml index 4b128c0828..9b838b5554 100644 --- a/crates/nu-cli/Cargo.toml +++ b/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" diff --git a/crates/nu-cli/src/app.rs b/crates/nu-cli/src/app.rs index 747867919a..4d04a3f325 100644 --- a/crates/nu-cli/src/app.rs +++ b/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 options_parser::{NuParser, OptionsParser}; - +use self::stopwatch::Stopwatch; +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 = { + let mut sw = Stopwatch::default(); + sw.start(); + sw.stop(); + Mutex::new(sw) + }; +} pub struct App { parser: Box, @@ -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") diff --git a/crates/nu-cli/src/app/options.rs b/crates/nu-cli/src/app/options.rs index 96e79a59f7..d68cf70504 100644 --- a/crates/nu-cli/src/app/options.rs +++ b/crates/nu-cli/src/app/options.rs @@ -10,6 +10,7 @@ pub struct CliOptions { pub stdin: bool, pub scripts: Vec, 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, } } } diff --git a/crates/nu-cli/src/app/stopwatch.rs b/crates/nu-cli/src/app/stopwatch.rs new file mode 100644 index 0000000000..e433782aff --- /dev/null +++ b/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, + /// The time the stopwatch was split last, if ever. + split_time: Option, + /// 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 + } +} diff --git a/crates/nu-cli/src/cli.rs b/crates/nu-cli/src/cli.rs index a8222d1c02..ac8ebf4912 100644 --- a/crates/nu-cli/src/cli.rs +++ b/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 {:?}", - startup_commands_start_time.elapsed() - ); + + if options.perf { + 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); diff --git a/crates/nu-command/src/commands/core_commands/nu_signature.rs b/crates/nu-command/src/commands/core_commands/nu_signature.rs index 020070fdb4..67ba1afc22 100644 --- a/crates/nu-command/src/commands/core_commands/nu_signature.rs +++ b/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, diff --git a/crates/nu-test-support/src/playground/director.rs b/crates/nu-test-support/src/playground/director.rs index c0b091fd15..59476576aa 100644 --- a/crates/nu-test-support/src/playground/director.rs +++ b/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 diff --git a/tests/fixtures/playground/config/default.toml b/tests/fixtures/playground/config/default.toml index 7ae2d00bdb..5939aacd41 100644 --- a/tests/fixtures/playground/config/default.toml +++ b/tests/fixtures/playground/config/default.toml @@ -1 +1,3 @@ skip_welcome_message = true +filesize_format = "auto" +rm_always_trash = false