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 }