From d64e381085eb4c9a7834b64af48e0c6c00901b1b Mon Sep 17 00:00:00 2001 From: Darren Schroeder <343840+fdncred@users.noreply.github.com> Date: Tue, 24 Jan 2023 14:28:59 -0600 Subject: [PATCH] add some startup performance metrics (#7851) # Description This PR changes the old performance logging with `Instant` timers. I'm not sure if this is the best way to do it but it does help reveal where time is being spent on startup. This is what it looks like when you launch nushell with `cargo run -- --log-level info`. I'm using the `info` log level exclusively for performance monitoring at this point. ![image](https://user-images.githubusercontent.com/343840/214372903-fdfa9c99-b846-47f3-8faf-bd6ed98df3a9.png) ## After Startup Since you're in the repl, you can continue running commands. Here's the output of `ls`, for instance. ![image](https://user-images.githubusercontent.com/343840/214373035-4d2f6e2d-5c1d-43d3-b997-51d79d496ba3.png) Note that the above screenshots are in debug mode, so they're much slower than release. # User-Facing Changes # Tests + Formatting Don't forget to add tests that cover your changes. Make sure you've run and fixed any issues with these commands: - `cargo fmt --all -- --check` to check standard code formatting (`cargo fmt --all` applies these changes) - `cargo clippy --workspace -- -D warnings -D clippy::unwrap_used -A clippy::needless_collect` to check that you're using the standard code style - `cargo test --workspace` to check that all tests pass # After Submitting If your PR had any user-facing changes, update [the documentation](https://github.com/nushell/nushell.github.io) after the PR is merged, if necessary. This will help us keep the docs up to date. --- Cargo.lock | 1 + crates/nu-cli/src/config_files.rs | 16 +++- crates/nu-cli/src/repl.rs | 130 ++++++++++++++++++++---------- crates/nu-cli/src/util.rs | 10 +++ crates/nu-utils/Cargo.toml | 5 +- crates/nu-utils/src/utils.rs | 13 +++ src/config_files.rs | 4 - src/main.rs | 117 +++++++++++++++++---------- 8 files changed, 202 insertions(+), 94 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 82851ca467..7bb9f82614 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2984,6 +2984,7 @@ name = "nu-utils" version = "0.74.1" dependencies = [ "crossterm_winapi", + "log", "lscolors", "num-format", "strip-ansi-escapes", diff --git a/crates/nu-cli/src/config_files.rs b/crates/nu-cli/src/config_files.rs index cf9fc7b045..61a9562808 100644 --- a/crates/nu-cli/src/config_files.rs +++ b/crates/nu-cli/src/config_files.rs @@ -1,7 +1,5 @@ use crate::util::{eval_source, report_error}; #[cfg(feature = "plugin")] -use log::info; -#[cfg(feature = "plugin")] use nu_parser::ParseError; #[cfg(feature = "plugin")] use nu_path::canonicalize_with; @@ -9,6 +7,8 @@ use nu_protocol::engine::{EngineState, Stack, StateWorkingSet}; #[cfg(feature = "plugin")] use nu_protocol::Spanned; use nu_protocol::{HistoryFileFormat, PipelineData}; +#[cfg(feature = "plugin")] +use nu_utils::utils::perf; use std::path::PathBuf; #[cfg(feature = "plugin")] @@ -24,6 +24,8 @@ pub fn read_plugin_file( plugin_file: Option>, storage_path: &str, ) { + let start_time = std::time::Instant::now(); + let mut plug_path = String::new(); // Reading signatures from signature file // The plugin.nu file stores the parsed signature collected from each registered plugin add_plugin_file(engine_state, plugin_file, storage_path); @@ -31,7 +33,7 @@ pub fn read_plugin_file( let plugin_path = engine_state.plugin_signatures.clone(); if let Some(plugin_path) = plugin_path { let plugin_filename = plugin_path.to_string_lossy(); - + plug_path = plugin_filename.to_string(); if let Ok(contents) = std::fs::read(&plugin_path) { eval_source( engine_state, @@ -43,7 +45,13 @@ pub fn read_plugin_file( } } - info!("read_plugin_file {}:{}:{}", file!(), line!(), column!()); + perf( + &format!("read_plugin_file {}", &plug_path), + start_time, + file!(), + line!(), + column!(), + ); } #[cfg(feature = "plugin")] diff --git a/crates/nu-cli/src/repl.rs b/crates/nu-cli/src/repl.rs index 1ca4a26787..360630f768 100644 --- a/crates/nu-cli/src/repl.rs +++ b/crates/nu-cli/src/repl.rs @@ -6,7 +6,7 @@ use crate::{ NuHighlighter, NuValidator, NushellPrompt, }; use crossterm::cursor::CursorShape; -use log::{info, trace, warn}; +use log::{trace, warn}; use miette::{IntoDiagnostic, Result}; use nu_color_config::StyleComputer; use nu_engine::{convert_env_values, eval_block, eval_block_with_early_return}; @@ -18,6 +18,7 @@ use nu_protocol::{ format_duration, BlockId, HistoryFileFormat, PipelineData, PositionalArg, ShellError, Span, Spanned, Type, Value, VarId, }; +use nu_utils::utils::perf; use reedline::{CursorConfig, DefaultHinter, EditCommand, Emacs, SqliteBackedHistory, Vi}; use std::{ io::{self, Write}, @@ -41,7 +42,7 @@ pub fn evaluate_repl( stack: &mut Stack, nushell_path: &str, prerun_command: Option>, - start_time: Instant, + entire_start_time: Instant, ) -> Result<()> { use reedline::{FileBackedHistory, Reedline, Signal}; @@ -59,18 +60,19 @@ pub fn evaluate_repl( let mut nu_prompt = NushellPrompt::new(); - info!( - "translate environment vars {}:{}:{}", - file!(), - line!(), - column!() - ); - + let start_time = std::time::Instant::now(); // Translate environment variables from Strings to Values if let Some(e) = convert_env_values(engine_state, stack) { let working_set = StateWorkingSet::new(engine_state); report_error(&working_set, &e); } + perf( + "translate env vars", + start_time, + file!(), + line!(), + column!(), + ); // seed env vars stack.add_env_var( @@ -80,15 +82,7 @@ pub fn evaluate_repl( stack.add_env_var("LAST_EXIT_CODE".into(), Value::int(0, Span::unknown())); - info!( - "load config initially {}:{}:{}", - file!(), - line!(), - column!() - ); - - info!("setup reedline {}:{}:{}", file!(), line!(), column!()); - + let mut start_time = std::time::Instant::now(); let mut line_editor = Reedline::create(); // Now that reedline is created, get the history session id and store it in engine_state @@ -97,16 +91,16 @@ pub fn evaluate_repl( .map(i64::from) .unwrap_or(0); engine_state.history_session_id = hist_sesh; + perf("setup reedline", start_time, file!(), line!(), column!()); let config = engine_state.get_config(); + start_time = std::time::Instant::now(); let history_path = crate::config_files::get_history_path( nushell_path, engine_state.config.history_file_format, ); if let Some(history_path) = history_path.as_deref() { - info!("setup history {}:{}:{}", file!(), line!(), column!()); - let history: Box = match engine_state.config.history_file_format { HistoryFileFormat::PlainText => Box::new( FileBackedHistory::with_file( @@ -121,7 +115,9 @@ pub fn evaluate_repl( }; line_editor = line_editor.with_history(history); }; + perf("setup history", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); let sys = sysinfo::System::new(); let show_banner = config.show_banner; @@ -134,6 +130,13 @@ pub fn evaluate_repl( println!("{}", nu_utils::strip_ansi_string_likely(banner)); } } + perf( + "get sysinfo/show banner", + start_time, + file!(), + line!(), + column!(), + ); if let Some(s) = prerun_command { eval_source( @@ -147,35 +150,35 @@ pub fn evaluate_repl( } loop { - info!( - "load config each loop {}:{}:{}", - file!(), - line!(), - column!() - ); + let loop_start_time = std::time::Instant::now(); let cwd = get_guaranteed_cwd(engine_state, stack); + start_time = std::time::Instant::now(); // Before doing anything, merge the environment from the previous REPL iteration into the // permanent state. if let Err(err) = engine_state.merge_env(stack, cwd) { report_error_new(engine_state, &err); } + perf("merge env", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); //Reset the ctrl-c handler if let Some(ctrlc) = &mut engine_state.ctrlc { ctrlc.store(false, Ordering::SeqCst); } + perf("reset ctrlc", start_time, file!(), line!(), column!()); + + start_time = std::time::Instant::now(); // Reset the SIGQUIT handler if let Some(sig_quit) = engine_state.get_sig_quit() { sig_quit.store(false, Ordering::SeqCst); } + perf("reset sig_quit", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); let config = engine_state.get_config(); - info!("setup colors {}:{}:{}", file!(), line!(), column!()); - - info!("update reedline {}:{}:{}", file!(), line!(), column!()); let engine_reference = std::sync::Arc::new(engine_state.clone()); // Find the configured cursor shapes for each mode @@ -188,6 +191,15 @@ pub fn evaluate_repl( )), emacs: Some(map_nucursorshape_to_cursorshape(config.cursor_shape_emacs)), }; + perf( + "get config/cursor config", + start_time, + file!(), + line!(), + column!(), + ); + + start_time = std::time::Instant::now(); line_editor = line_editor .with_highlighter(Box::new(NuHighlighter { @@ -205,9 +217,11 @@ pub fn evaluate_repl( .with_partial_completions(config.partial_completions) .with_ansi_colors(config.use_ansi_coloring) .with_cursor_config(cursor_config); + perf("reedline builder", start_time, file!(), line!(), column!()); let style_computer = StyleComputer::from_config(engine_state, stack); + start_time = std::time::Instant::now(); line_editor = if config.use_ansi_coloring { line_editor.with_hinter(Box::new({ // As of Nov 2022, "hints" color_config closures only get `null` passed in. @@ -217,13 +231,23 @@ pub fn evaluate_repl( } else { line_editor.disable_hints() }; + perf( + "reedline coloring/style_computer", + start_time, + file!(), + line!(), + column!(), + ); + start_time = std::time::Instant::now(); line_editor = add_menus(line_editor, engine_reference, stack, config).unwrap_or_else(|e| { let working_set = StateWorkingSet::new(engine_state); report_error(&working_set, &e); Reedline::create() }); + perf("reedline menus", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); let buffer_editor = if !config.buffer_editor.is_empty() { Some(config.buffer_editor.clone()) } else { @@ -244,17 +268,23 @@ pub fn evaluate_repl( } else { line_editor }; + perf( + "reedline buffer_editor", + start_time, + file!(), + line!(), + column!(), + ); + start_time = std::time::Instant::now(); if config.sync_history_on_enter { - info!("sync history {}:{}:{}", file!(), line!(), column!()); - if let Err(e) = line_editor.sync_history() { warn!("Failed to sync history: {}", e); } } + perf("sync_history", start_time, file!(), line!(), column!()); - info!("setup keybindings {}:{}:{}", file!(), line!(), column!()); - + start_time = std::time::Instant::now(); // Changing the line editor based on the found keybindings line_editor = match create_keybindings(config) { Ok(keybindings) => match keybindings { @@ -276,9 +306,9 @@ pub fn evaluate_repl( line_editor } }; + perf("keybindings", start_time, file!(), line!(), column!()); - info!("prompt_update {}:{}:{}", file!(), line!(), column!()); - + start_time = std::time::Instant::now(); // Right before we start our prompt and take input from the user, // fire the "pre_prompt" hook if let Some(hook) = config.hooks.pre_prompt.clone() { @@ -286,7 +316,9 @@ pub fn evaluate_repl( report_error_new(engine_state, &err); } } + perf("pre-prompt hook", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); // Next, check all the environment variables they ask for // fire the "env_change" hook let config = engine_state.get_config(); @@ -295,26 +327,23 @@ pub fn evaluate_repl( { report_error_new(engine_state, &error) } + perf("env-change hook", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); let config = engine_state.get_config(); let prompt = prompt_update::update_prompt(config, engine_state, stack, &mut nu_prompt); + perf("update_prompt", start_time, file!(), line!(), column!()); entry_num += 1; - info!( - "finished setup, starting repl {}:{}:{}", - file!(), - line!(), - column!() - ); - if entry_num == 1 && show_banner { println!( "Startup Time: {}", - format_duration(start_time.elapsed().as_nanos() as i64) + format_duration(entire_start_time.elapsed().as_nanos() as i64) ); } + start_time = std::time::Instant::now(); let input = line_editor.read_line(prompt); let shell_integration = config.shell_integration; @@ -550,6 +579,21 @@ pub fn evaluate_repl( } } } + perf( + "processing line editor input", + start_time, + file!(), + line!(), + column!(), + ); + + perf( + "finished repl loop", + loop_start_time, + file!(), + line!(), + column!(), + ); } Ok(()) diff --git a/crates/nu-cli/src/util.rs b/crates/nu-cli/src/util.rs index 13dbf89ff0..d1560a8453 100644 --- a/crates/nu-cli/src/util.rs +++ b/crates/nu-cli/src/util.rs @@ -9,6 +9,7 @@ use nu_protocol::{ }; #[cfg(windows)] use nu_utils::enable_vt_processing; +use nu_utils::utils::perf; use std::path::{Path, PathBuf}; // This will collect environment variables from std::env and adds them to a stack. @@ -204,6 +205,8 @@ pub fn eval_source( fname: &str, input: PipelineData, ) -> bool { + let start_time = std::time::Instant::now(); + let (block, delta) = { let mut working_set = StateWorkingSet::new(engine_state); let (output, err) = parse( @@ -282,6 +285,13 @@ pub fn eval_source( return false; } } + perf( + &format!("eval_source {}", &fname), + start_time, + file!(), + line!(), + column!(), + ); true } diff --git a/crates/nu-utils/Cargo.toml b/crates/nu-utils/Cargo.toml index ca7803298e..49d2728abd 100644 --- a/crates/nu-utils/Cargo.toml +++ b/crates/nu-utils/Cargo.toml @@ -1,10 +1,10 @@ [package] authors = ["The Nushell Project Developers"] description = "Nushell utility functions" -repository = "https://github.com/nushell/nushell/tree/main/crates/nu-utils" edition = "2021" license = "MIT" name = "nu-utils" +repository = "https://github.com/nushell/nushell/tree/main/crates/nu-utils" version = "0.74.1" # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html @@ -13,10 +13,11 @@ name = "utils" path = "src/main.rs" [dependencies] +log = "0.4" lscolors = { version = "0.12.0", features = ["crossterm"], default-features = false } num-format = { version = "0.4.3" } -sys-locale = "0.2.1" strip-ansi-escapes = "0.1.1" +sys-locale = "0.2.1" [target.'cfg(windows)'.dependencies] crossterm_winapi = "0.9.0" diff --git a/crates/nu-utils/src/utils.rs b/crates/nu-utils/src/utils.rs index d3e789a270..1e4ed4c58f 100644 --- a/crates/nu-utils/src/utils.rs +++ b/crates/nu-utils/src/utils.rs @@ -1,3 +1,4 @@ +use log::info; use lscolors::LsColors; use std::io::{Result, Write}; @@ -62,3 +63,15 @@ pub fn get_ls_colors(lscolors_env_string: Option) -> LsColors { LsColors::from_string("st=0:di=0;38;5;81:so=0;38;5;16;48;5;203:ln=0;38;5;203:cd=0;38;5;203;48;5;236:ex=1;38;5;203:or=0;38;5;16;48;5;203:fi=0:bd=0;38;5;81;48;5;236:ow=0:mi=0;38;5;16;48;5;203:*~=0;38;5;243:no=0:tw=0:pi=0;38;5;16;48;5;81:*.z=4;38;5;203:*.t=0;38;5;48:*.o=0;38;5;243:*.d=0;38;5;48:*.a=1;38;5;203:*.c=0;38;5;48:*.m=0;38;5;48:*.p=0;38;5;48:*.r=0;38;5;48:*.h=0;38;5;48:*.ml=0;38;5;48:*.ll=0;38;5;48:*.gv=0;38;5;48:*.cp=0;38;5;48:*.xz=4;38;5;203:*.hs=0;38;5;48:*css=0;38;5;48:*.ui=0;38;5;149:*.pl=0;38;5;48:*.ts=0;38;5;48:*.gz=4;38;5;203:*.so=1;38;5;203:*.cr=0;38;5;48:*.fs=0;38;5;48:*.bz=4;38;5;203:*.ko=1;38;5;203:*.as=0;38;5;48:*.sh=0;38;5;48:*.pp=0;38;5;48:*.el=0;38;5;48:*.py=0;38;5;48:*.lo=0;38;5;243:*.bc=0;38;5;243:*.cc=0;38;5;48:*.pm=0;38;5;48:*.rs=0;38;5;48:*.di=0;38;5;48:*.jl=0;38;5;48:*.rb=0;38;5;48:*.md=0;38;5;185:*.js=0;38;5;48:*.go=0;38;5;48:*.vb=0;38;5;48:*.hi=0;38;5;243:*.kt=0;38;5;48:*.hh=0;38;5;48:*.cs=0;38;5;48:*.mn=0;38;5;48:*.nb=0;38;5;48:*.7z=4;38;5;203:*.ex=0;38;5;48:*.rm=0;38;5;208:*.ps=0;38;5;186:*.td=0;38;5;48:*.la=0;38;5;243:*.aux=0;38;5;243:*.xmp=0;38;5;149:*.mp4=0;38;5;208:*.rpm=4;38;5;203:*.m4a=0;38;5;208:*.zip=4;38;5;203:*.dll=1;38;5;203:*.bcf=0;38;5;243:*.awk=0;38;5;48:*.aif=0;38;5;208:*.zst=4;38;5;203:*.bak=0;38;5;243:*.tgz=4;38;5;203:*.com=1;38;5;203:*.clj=0;38;5;48:*.sxw=0;38;5;186:*.vob=0;38;5;208:*.fsx=0;38;5;48:*.doc=0;38;5;186:*.mkv=0;38;5;208:*.tbz=4;38;5;203:*.ogg=0;38;5;208:*.wma=0;38;5;208:*.mid=0;38;5;208:*.kex=0;38;5;186:*.out=0;38;5;243:*.ltx=0;38;5;48:*.sql=0;38;5;48:*.ppt=0;38;5;186:*.tex=0;38;5;48:*.odp=0;38;5;186:*.log=0;38;5;243:*.arj=4;38;5;203:*.ipp=0;38;5;48:*.sbt=0;38;5;48:*.jpg=0;38;5;208:*.yml=0;38;5;149:*.txt=0;38;5;185:*.csv=0;38;5;185:*.dox=0;38;5;149:*.pro=0;38;5;149:*.bst=0;38;5;149:*TODO=1:*.mir=0;38;5;48:*.bat=1;38;5;203:*.m4v=0;38;5;208:*.pod=0;38;5;48:*.cfg=0;38;5;149:*.pas=0;38;5;48:*.tml=0;38;5;149:*.bib=0;38;5;149:*.ini=0;38;5;149:*.apk=4;38;5;203:*.h++=0;38;5;48:*.pyc=0;38;5;243:*.img=4;38;5;203:*.rst=0;38;5;185:*.swf=0;38;5;208:*.htm=0;38;5;185:*.ttf=0;38;5;208:*.elm=0;38;5;48:*hgrc=0;38;5;149:*.bmp=0;38;5;208:*.fsi=0;38;5;48:*.pgm=0;38;5;208:*.dpr=0;38;5;48:*.xls=0;38;5;186:*.tcl=0;38;5;48:*.mli=0;38;5;48:*.ppm=0;38;5;208:*.bbl=0;38;5;243:*.lua=0;38;5;48:*.asa=0;38;5;48:*.pbm=0;38;5;208:*.avi=0;38;5;208:*.def=0;38;5;48:*.mov=0;38;5;208:*.hxx=0;38;5;48:*.tif=0;38;5;208:*.fon=0;38;5;208:*.zsh=0;38;5;48:*.png=0;38;5;208:*.inc=0;38;5;48:*.jar=4;38;5;203:*.swp=0;38;5;243:*.pid=0;38;5;243:*.gif=0;38;5;208:*.ind=0;38;5;243:*.erl=0;38;5;48:*.ilg=0;38;5;243:*.eps=0;38;5;208:*.tsx=0;38;5;48:*.git=0;38;5;243:*.inl=0;38;5;48:*.rtf=0;38;5;186:*.hpp=0;38;5;48:*.kts=0;38;5;48:*.deb=4;38;5;203:*.svg=0;38;5;208:*.pps=0;38;5;186:*.ps1=0;38;5;48:*.c++=0;38;5;48:*.cpp=0;38;5;48:*.bsh=0;38;5;48:*.php=0;38;5;48:*.exs=0;38;5;48:*.toc=0;38;5;243:*.mp3=0;38;5;208:*.epp=0;38;5;48:*.rar=4;38;5;203:*.wav=0;38;5;208:*.xlr=0;38;5;186:*.tmp=0;38;5;243:*.cxx=0;38;5;48:*.iso=4;38;5;203:*.dmg=4;38;5;203:*.gvy=0;38;5;48:*.bin=4;38;5;203:*.wmv=0;38;5;208:*.blg=0;38;5;243:*.ods=0;38;5;186:*.psd=0;38;5;208:*.mpg=0;38;5;208:*.dot=0;38;5;48:*.cgi=0;38;5;48:*.xml=0;38;5;185:*.htc=0;38;5;48:*.ics=0;38;5;186:*.bz2=4;38;5;203:*.tar=4;38;5;203:*.csx=0;38;5;48:*.ico=0;38;5;208:*.sxi=0;38;5;186:*.nix=0;38;5;149:*.pkg=4;38;5;203:*.bag=4;38;5;203:*.fnt=0;38;5;208:*.idx=0;38;5;243:*.xcf=0;38;5;208:*.exe=1;38;5;203:*.flv=0;38;5;208:*.fls=0;38;5;243:*.otf=0;38;5;208:*.vcd=4;38;5;203:*.vim=0;38;5;48:*.sty=0;38;5;243:*.pdf=0;38;5;186:*.odt=0;38;5;186:*.purs=0;38;5;48:*.h264=0;38;5;208:*.jpeg=0;38;5;208:*.dart=0;38;5;48:*.pptx=0;38;5;186:*.lock=0;38;5;243:*.bash=0;38;5;48:*.rlib=0;38;5;243:*.hgrc=0;38;5;149:*.psm1=0;38;5;48:*.toml=0;38;5;149:*.tbz2=4;38;5;203:*.yaml=0;38;5;149:*.make=0;38;5;149:*.orig=0;38;5;243:*.html=0;38;5;185:*.fish=0;38;5;48:*.diff=0;38;5;48:*.xlsx=0;38;5;186:*.docx=0;38;5;186:*.json=0;38;5;149:*.psd1=0;38;5;48:*.tiff=0;38;5;208:*.flac=0;38;5;208:*.java=0;38;5;48:*.less=0;38;5;48:*.mpeg=0;38;5;208:*.conf=0;38;5;149:*.lisp=0;38;5;48:*.epub=0;38;5;186:*.cabal=0;38;5;48:*.patch=0;38;5;48:*.shtml=0;38;5;185:*.class=0;38;5;243:*.xhtml=0;38;5;185:*.mdown=0;38;5;185:*.dyn_o=0;38;5;243:*.cache=0;38;5;243:*.swift=0;38;5;48:*README=0;38;5;16;48;5;186:*passwd=0;38;5;149:*.ipynb=0;38;5;48:*shadow=0;38;5;149:*.toast=4;38;5;203:*.cmake=0;38;5;149:*.scala=0;38;5;48:*.dyn_hi=0;38;5;243:*.matlab=0;38;5;48:*.config=0;38;5;149:*.gradle=0;38;5;48:*.groovy=0;38;5;48:*.ignore=0;38;5;149:*LICENSE=0;38;5;249:*TODO.md=1:*COPYING=0;38;5;249:*.flake8=0;38;5;149:*INSTALL=0;38;5;16;48;5;186:*setup.py=0;38;5;149:*.gemspec=0;38;5;149:*.desktop=0;38;5;149:*Makefile=0;38;5;149:*Doxyfile=0;38;5;149:*TODO.txt=1:*README.md=0;38;5;16;48;5;186:*.kdevelop=0;38;5;149:*.rgignore=0;38;5;149:*configure=0;38;5;149:*.DS_Store=0;38;5;243:*.fdignore=0;38;5;149:*COPYRIGHT=0;38;5;249:*.markdown=0;38;5;185:*.cmake.in=0;38;5;149:*.gitconfig=0;38;5;149:*INSTALL.md=0;38;5;16;48;5;186:*CODEOWNERS=0;38;5;149:*.gitignore=0;38;5;149:*Dockerfile=0;38;5;149:*SConstruct=0;38;5;149:*.scons_opt=0;38;5;243:*README.txt=0;38;5;16;48;5;186:*SConscript=0;38;5;149:*.localized=0;38;5;243:*.travis.yml=0;38;5;186:*Makefile.in=0;38;5;243:*.gitmodules=0;38;5;149:*LICENSE-MIT=0;38;5;249:*Makefile.am=0;38;5;149:*INSTALL.txt=0;38;5;16;48;5;186:*MANIFEST.in=0;38;5;149:*.synctex.gz=0;38;5;243:*.fdb_latexmk=0;38;5;243:*CONTRIBUTORS=0;38;5;16;48;5;186:*configure.ac=0;38;5;149:*.applescript=0;38;5;48:*appveyor.yml=0;38;5;186:*.clang-format=0;38;5;149:*.gitattributes=0;38;5;149:*LICENSE-APACHE=0;38;5;249:*CMakeCache.txt=0;38;5;243:*CMakeLists.txt=0;38;5;149:*CONTRIBUTORS.md=0;38;5;16;48;5;186:*requirements.txt=0;38;5;149:*CONTRIBUTORS.txt=0;38;5;16;48;5;186:*.sconsign.dblite=0;38;5;243:*package-lock.json=0;38;5;243:*.CFUserTextEncoding=0;38;5;243") } } + +// Log some performance metrics (green text with yellow timings) +pub fn perf(msg: &str, dur: std::time::Instant, file: &str, line: u32, column: u32) { + info!( + "perf: {}:{}:{} \x1b[32m{}\x1b[0m took \x1b[33m{:?}\x1b[0m", + file, + line, + column, + msg, + dur.elapsed(), + ); +} diff --git a/src/config_files.rs b/src/config_files.rs index e54fad9825..15dd03f576 100644 --- a/src/config_files.rs +++ b/src/config_files.rs @@ -110,8 +110,6 @@ pub(crate) fn read_config_file( eval_config_contents(config_path, engine_state, stack); } - - info!("read_config_file {}:{}:{}", file!(), line!(), column!()); } pub(crate) fn read_loginshell_file(engine_state: &mut EngineState, stack: &mut Stack) { @@ -200,8 +198,6 @@ pub(crate) fn setup_config( #[cfg(feature = "plugin")] read_plugin_file(engine_state, stack, plugin_file, NUSHELL_FOLDER); - info!("read_config_file {}:{}:{}", file!(), line!(), column!()); - read_config_file(engine_state, stack, env_file, true); read_config_file(engine_state, stack, config_file, false); diff --git a/src/main.rs b/src/main.rs index a3620ecf9d..afe8f9b642 100644 --- a/src/main.rs +++ b/src/main.rs @@ -15,7 +15,7 @@ use crate::{ logger::{configure, logger}, terminal::acquire_terminal, }; -use log::{info, Level}; +use log::Level; use miette::Result; #[cfg(feature = "plugin")] use nu_cli::read_plugin_file; @@ -26,16 +26,17 @@ use nu_cli::{ use nu_command::create_default_context; use nu_parser::{escape_for_script_arg, escape_quote_string}; use nu_protocol::{util::BufferedReader, PipelineData, RawStream}; +use nu_utils::utils::perf; use signals::{ctrlc_protection, sigquit_protection}; use std::{ io::BufReader, str::FromStr, sync::{atomic::AtomicBool, Arc}, - time::Instant, }; fn main() -> Result<()> { - let start_time = Instant::now(); + let entire_start_time = std::time::Instant::now(); + let mut start_time = std::time::Instant::now(); let miette_hook = std::panic::take_hook(); std::panic::set_hook(Box::new(move |x| { crossterm::terminal::disable_raw_mode().expect("unable to disable raw mode"); @@ -113,37 +114,6 @@ fn main() -> Result<()> { let parsed_nu_cli_args = parse_commandline_args(&nushell_commandline_args, &mut engine_state) .unwrap_or_else(|_| std::process::exit(1)); - set_config_path( - &mut engine_state, - &init_cwd, - "config.nu", - "config-path", - &parsed_nu_cli_args.config_file, - ); - - set_config_path( - &mut engine_state, - &init_cwd, - "env.nu", - "env-path", - &parsed_nu_cli_args.env_file, - ); - - // keep this condition in sync with the branches below - acquire_terminal( - parsed_nu_cli_args.commands.is_none() - && (script_name.is_empty() || parsed_nu_cli_args.interactive_shell.is_some()), - ); - - if let Some(t) = parsed_nu_cli_args.threads { - // 0 means to let rayon decide how many threads to use - let threads = t.as_i64().unwrap_or(0); - rayon::ThreadPoolBuilder::new() - .num_threads(threads as usize) - .build_global() - .expect("error setting number of threads"); - } - if let Some(level) = parsed_nu_cli_args.log_level.map(|level| level.item) { let level = if Level::from_str(&level).is_ok() { level @@ -159,9 +129,48 @@ fn main() -> Result<()> { .unwrap_or_else(|| "stderr".to_string()); logger(|builder| configure(&level, &target, builder))?; - info!("start logging {}:{}:{}", file!(), line!(), column!()); + // info!("start logging {}:{}:{}", file!(), line!(), column!()); + perf("start logging", start_time, file!(), line!(), column!()); } + start_time = std::time::Instant::now(); + set_config_path( + &mut engine_state, + &init_cwd, + "config.nu", + "config-path", + &parsed_nu_cli_args.config_file, + ); + + set_config_path( + &mut engine_state, + &init_cwd, + "env.nu", + "env-path", + &parsed_nu_cli_args.env_file, + ); + perf("set_config_path", start_time, file!(), line!(), column!()); + + start_time = std::time::Instant::now(); + // keep this condition in sync with the branches below + acquire_terminal( + parsed_nu_cli_args.commands.is_none() + && (script_name.is_empty() || parsed_nu_cli_args.interactive_shell.is_some()), + ); + perf("acquire_terminal", start_time, file!(), line!(), column!()); + + start_time = std::time::Instant::now(); + if let Some(t) = parsed_nu_cli_args.threads { + // 0 means to let rayon decide how many threads to use + let threads = t.as_i64().unwrap_or(0); + rayon::ThreadPoolBuilder::new() + .num_threads(threads as usize) + .build_global() + .expect("error setting number of threads"); + } + perf("set rayon threads", start_time, file!(), line!(), column!()); + + start_time = std::time::Instant::now(); if let Some(testbin) = &parsed_nu_cli_args.testbin { // Call out to the correct testbin match testbin.item.as_str() { @@ -181,6 +190,9 @@ fn main() -> Result<()> { } std::process::exit(0) } + perf("run test_bins", start_time, file!(), line!(), column!()); + + start_time = std::time::Instant::now(); let input = if let Some(redirect_stdin) = &parsed_nu_cli_args.redirect_stdin { let stdin = std::io::stdin(); let buf_reader = BufReader::new(stdin); @@ -201,15 +213,17 @@ fn main() -> Result<()> { } else { PipelineData::empty() }; + perf("redirect stdin", start_time, file!(), line!(), column!()); - info!("redirect_stdin {}:{}:{}", file!(), line!(), column!()); - + start_time = std::time::Instant::now(); // First, set up env vars as strings only gather_parent_env_vars(&mut engine_state, &init_cwd); + perf("gather env vars", start_time, file!(), line!(), column!()); let mut stack = nu_protocol::engine::Stack::new(); if let Some(commands) = &parsed_nu_cli_args.commands { + start_time = std::time::Instant::now(); #[cfg(feature = "plugin")] read_plugin_file( &mut engine_state, @@ -217,7 +231,9 @@ fn main() -> Result<()> { parsed_nu_cli_args.plugin_file, NUSHELL_FOLDER, ); + perf("read plugins", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); // only want to load config and env if relative argument is provided. if parsed_nu_cli_args.env_file.is_some() { config_files::read_config_file( @@ -229,7 +245,9 @@ fn main() -> Result<()> { } else { config_files::read_default_env_file(&mut engine_state, &mut stack) } + perf("read env.nu", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); if parsed_nu_cli_args.config_file.is_some() { config_files::read_config_file( &mut engine_state, @@ -238,7 +256,9 @@ fn main() -> Result<()> { false, ); } + perf("read config.nu", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); let ret_val = evaluate_commands( commands, &mut engine_state, @@ -246,13 +266,16 @@ fn main() -> Result<()> { input, parsed_nu_cli_args.table_mode, ); - info!("-c command execution {}:{}:{}", file!(), line!(), column!()); + perf("evaluate_commands", start_time, file!(), line!(), column!()); + match ret_val { Ok(Some(exit_code)) => std::process::exit(exit_code as i32), Ok(None) => Ok(()), Err(e) => Err(e), } } else if !script_name.is_empty() && parsed_nu_cli_args.interactive_shell.is_none() { + start_time = std::time::Instant::now(); + #[cfg(feature = "plugin")] read_plugin_file( &mut engine_state, @@ -260,7 +283,9 @@ fn main() -> Result<()> { parsed_nu_cli_args.plugin_file, NUSHELL_FOLDER, ); + perf("read plugins", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); // only want to load config and env if relative argument is provided. if parsed_nu_cli_args.env_file.is_some() { config_files::read_config_file( @@ -272,7 +297,9 @@ fn main() -> Result<()> { } else { config_files::read_default_env_file(&mut engine_state, &mut stack) } + perf("read env.nu", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); if parsed_nu_cli_args.config_file.is_some() { config_files::read_config_file( &mut engine_state, @@ -281,7 +308,9 @@ fn main() -> Result<()> { false, ); } + perf("read config.nu", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); let ret_val = evaluate_file( script_name, &args_to_script, @@ -289,7 +318,9 @@ fn main() -> Result<()> { &mut stack, input, ); + perf("evaluate_file", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); let last_exit_code = stack.get_env_var(&engine_state, "LAST_EXIT_CODE"); if let Some(last_exit_code) = last_exit_code { let value = last_exit_code.as_integer(); @@ -299,10 +330,12 @@ fn main() -> Result<()> { } } } - info!("eval_file execution {}:{}:{}", file!(), line!(), column!()); + perf("get exit code", start_time, file!(), line!(), column!()); ret_val } else { + start_time = std::time::Instant::now(); + setup_config( &mut engine_state, &mut stack, @@ -312,15 +345,17 @@ fn main() -> Result<()> { parsed_nu_cli_args.env_file, parsed_nu_cli_args.login_shell.is_some(), ); + perf("setup_config", start_time, file!(), line!(), column!()); + start_time = std::time::Instant::now(); let ret_val = evaluate_repl( &mut engine_state, &mut stack, config_files::NUSHELL_FOLDER, parsed_nu_cli_args.execute, - start_time, + entire_start_time, ); - info!("repl eval {}:{}:{}", file!(), line!(), column!()); + perf("evaluate_repl", start_time, file!(), line!(), column!()); ret_val }