diff --git a/Cargo.lock b/Cargo.lock index 08ac02310..eb1ae4fe3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2094,6 +2094,7 @@ name = "nu" version = "0.59.0" dependencies = [ "assert_cmd", + "chrono", "crossterm", "crossterm_winapi", "ctrlc", diff --git a/Cargo.toml b/Cargo.toml index 1b1c085ea..7c8e78b09 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -30,37 +30,35 @@ members = [ ] [dependencies] -reedline = { git = "https://github.com/nushell/reedline", branch = "main" } - +chrono = "0.4.19" crossterm = "0.22.*" +crossterm_winapi = "0.9.0" +ctrlc = "3.2.1" +# lazy_static = "1.4.0" +log = "0.4" +miette = "3.0.0" +nu-ansi-term = "0.42.0" nu-cli = { path="./crates/nu-cli", version = "0.59.0" } +nu-color-config = { path = "./crates/nu-color-config", version = "0.59.0" } nu-command = { path="./crates/nu-command", version = "0.59.0" } nu-engine = { path="./crates/nu-engine", version = "0.59.0" } nu-json = { path="./crates/nu-json", version = "0.59.0" } nu-parser = { path="./crates/nu-parser", version = "0.59.0" } nu-path = { path="./crates/nu-path", version = "0.59.0" } +nu-plugin = { path = "./crates/nu-plugin", optional = true, version = "0.59.0" } nu-pretty-hex = { path = "./crates/nu-pretty-hex", version = "0.59.0" } nu-protocol = { path = "./crates/nu-protocol", version = "0.59.0" } -nu-plugin = { path = "./crates/nu-plugin", optional = true, version = "0.59.0" } nu-system = { path = "./crates/nu-system", version = "0.59.0" } nu-table = { path = "./crates/nu-table", version = "0.59.0" } nu-term-grid = { path = "./crates/nu-term-grid", version = "0.59.0" } -# nu-ansi-term = { path = "./crates/nu-ansi-term", version = "0.59.0" } -nu-ansi-term = "0.42.0" - -nu-color-config = { path = "./crates/nu-color-config", version = "0.59.0" } - -miette = "3.0.0" -ctrlc = "3.2.1" -crossterm_winapi = "0.9.0" -log = "0.4" pretty_env_logger = "0.4.0" +reedline = { git = "https://github.com/nushell/reedline", branch = "main" } # mimalloc = { version = "*", default-features = false } - -nu_plugin_inc = { version = "0.59.0", path = "./crates/nu_plugin_inc", optional = true } +# Plugins nu_plugin_example = { version = "0.59.0", path = "./crates/nu_plugin_example", optional = true } nu_plugin_gstat = { version = "0.59.0", path = "./crates/nu_plugin_gstat", optional = true } +nu_plugin_inc = { version = "0.59.0", path = "./crates/nu_plugin_inc", optional = true } nu_plugin_query = { version = "0.59.0", path = "./crates/nu_plugin_query", optional = true } [dev-dependencies] @@ -75,23 +73,9 @@ itertools = "0.10.3" [features] plugin = ["nu-plugin", "nu-parser/plugin", "nu-command/plugin", "nu-protocol/plugin", "nu-engine/plugin"] -default = [ - "plugin", - "inc", - "example", - "which" - ] - +default = ["plugin", "inc", "example", "which"] stable = ["default"] - -extra = [ - "default", - "dataframe", - "gstat", - "zip-support", - "query", -] - +extra = [ "default", "dataframe", "gstat", "zip-support", "query", ] wasi = ["inc"] # Stable (Default) diff --git a/crates/nu-command/tests/commands/cp.rs b/crates/nu-command/tests/commands/cp.rs index 9fe1272b7..81fe7c1e3 100644 --- a/crates/nu-command/tests/commands/cp.rs +++ b/crates/nu-command/tests/commands/cp.rs @@ -127,7 +127,7 @@ fn copies_using_path_with_wildcard() { Playground::setup("cp_test_6", |dirs, _| { nu!( cwd: dirs.formats(), - "cp ../formats/* {}", dirs.test() + "cp -r ../formats/* {}", dirs.test() ); assert!(files_exist_at( @@ -149,7 +149,7 @@ fn copies_using_a_glob() { Playground::setup("cp_test_7", |dirs, _| { nu!( cwd: dirs.formats(), - "cp * {}", dirs.test() + "cp -r * {}", dirs.test() ); assert!(files_exist_at( diff --git a/src/commands.rs b/src/commands.rs index 3fffbf5cc..51e8a9ce7 100644 --- a/src/commands.rs +++ b/src/commands.rs @@ -1,14 +1,14 @@ +use crate::is_perf_true; +use crate::utils::{gather_parent_env_vars, report_error}; +use log::info; use miette::Result; use nu_engine::{convert_env_values, eval_block}; -use std::path::Path; - use nu_parser::{lex, lite_parse, parse_block, trim_quotes}; use nu_protocol::{ engine::{EngineState, StateDelta, StateWorkingSet}, Config, PipelineData, Span, Spanned, Value, CONFIG_VARIABLE_ID, }; - -use crate::utils::{gather_parent_env_vars, report_error}; +use std::path::Path; pub(crate) fn evaluate( commands: &Spanned, @@ -123,5 +123,9 @@ pub(crate) fn evaluate( } } + if is_perf_true() { + info!("evaluate {}:{}:{}", file!(), line!(), column!()); + } + Ok(()) } diff --git a/src/config_files.rs b/src/config_files.rs index ea053051f..5adab05d1 100644 --- a/src/config_files.rs +++ b/src/config_files.rs @@ -1,4 +1,6 @@ +use crate::is_perf_true; use crate::utils::{eval_source, report_error}; +use log::info; use nu_protocol::engine::{EngineState, Stack, StateDelta, StateWorkingSet}; use std::path::PathBuf; @@ -22,6 +24,9 @@ pub(crate) fn read_plugin_file(engine_state: &mut EngineState, stack: &mut Stack eval_source(engine_state, stack, &contents, &plugin_filename); } } + if is_perf_true() { + info!("read_plugin_file {}:{}:{}", file!(), line!(), column!()); + } } pub(crate) fn read_config_file(engine_state: &mut EngineState, stack: &mut Stack) { @@ -63,6 +68,9 @@ pub(crate) fn read_config_file(engine_state: &mut EngineState, stack: &mut Stack } } } + if is_perf_true() { + info!("read_config_file {}:{}:{}", file!(), line!(), column!()); + } } pub(crate) fn create_history_path() -> Option { diff --git a/src/eval_file.rs b/src/eval_file.rs index 0fb38d387..7a8e1653f 100644 --- a/src/eval_file.rs +++ b/src/eval_file.rs @@ -1,3 +1,6 @@ +use crate::is_perf_true; +use crate::utils::{gather_parent_env_vars, report_error}; +use log::info; use log::trace; use miette::{IntoDiagnostic, Result}; use nu_engine::{convert_env_values, eval_block}; @@ -9,8 +12,6 @@ use nu_protocol::{ }; use std::{io::Write, path::PathBuf}; -use crate::utils::{gather_parent_env_vars, report_error}; - /// Main function used when a file path is found as argument for nu pub(crate) fn evaluate( path: String, @@ -135,6 +136,10 @@ pub(crate) fn evaluate( } } + if is_perf_true() { + info!("evaluate {}:{}:{}", file!(), line!(), column!()); + } + Ok(()) } diff --git a/src/logger.rs b/src/logger.rs index 937dbe8ba..3b84f27bb 100644 --- a/src/logger.rs +++ b/src/logger.rs @@ -1,14 +1,50 @@ +use chrono::{DateTime, FixedOffset, Utc}; +use core::fmt; +use log::Level; use log::LevelFilter; use nu_protocol::ShellError; +use pretty_env_logger::env_logger::fmt::Color; use pretty_env_logger::env_logger::Builder; +use std::io::Write; +use std::sync::atomic::{AtomicUsize, Ordering}; pub fn logger(f: impl FnOnce(&mut Builder) -> Result<(), ShellError>) -> Result<(), ShellError> { - let mut builder = pretty_env_logger::formatted_builder(); + let mut builder = my_formatted_timed_builder(); f(&mut builder)?; let _ = builder.try_init(); Ok(()) } +pub fn my_formatted_timed_builder() -> Builder { + let mut builder = Builder::new(); + + builder.format(|f, record| { + let target = record.target(); + let max_width = max_target_width(target); + + let mut style = f.style(); + let level = colored_level(&mut style, record.level()); + + let mut style = f.style(); + let target = style.set_bold(true).value(Padded { + value: target, + width: max_width, + }); + + let dt = match DateTime::parse_from_rfc3339(&f.timestamp_millis().to_string()) { + Ok(d) => d, + Err(_) => { + let n = Utc::now(); + DateTime::::from(n) + } + }; + let time = dt.format("%Y-%m-%d %I:%M:%S%.3f %p"); + writeln!(f, "{}|{}|{}|{}", time, level, target, record.args(),) + }); + + builder +} + pub fn configure(level: &str, logger: &mut Builder) -> Result<(), ShellError> { let level = match level { "error" => LevelFilter::Error, @@ -47,3 +83,39 @@ pub fn configure(level: &str, logger: &mut Builder) -> Result<(), ShellError> { // Ok(()) // } + +fn colored_level<'a>( + style: &'a mut pretty_env_logger::env_logger::fmt::Style, + level: Level, +) -> pretty_env_logger::env_logger::fmt::StyledValue<'a, &'static str> { + match level { + Level::Trace => style.set_color(Color::Magenta).value("TRACE"), + Level::Debug => style.set_color(Color::Blue).value("DEBUG"), + Level::Info => style.set_color(Color::Green).value("INFO "), + Level::Warn => style.set_color(Color::Yellow).value("WARN "), + Level::Error => style.set_color(Color::Red).value("ERROR"), + } +} + +static MAX_MODULE_WIDTH: AtomicUsize = AtomicUsize::new(0); + +fn max_target_width(target: &str) -> usize { + let max_width = MAX_MODULE_WIDTH.load(Ordering::Relaxed); + if max_width < target.len() { + MAX_MODULE_WIDTH.store(target.len(), Ordering::Relaxed); + target.len() + } else { + max_width + } +} + +struct Padded { + value: T, + width: usize, +} + +impl fmt::Display for Padded { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + write!(f, "{: = RefCell::new(false) } + fn main() -> Result<()> { // miette::set_panic_hook(); let miette_hook = std::panic::take_hook(); @@ -99,6 +102,7 @@ fn main() -> Result<()> { || arg == "--debug" || arg == "--loglevel" || arg == "--config-file" + || arg == "--perf" { collect_arg_nushell = true; } @@ -113,12 +117,24 @@ fn main() -> Result<()> { let nushell_commandline_args = args_to_nushell.join(" "); - let nushell_config = + let parsed_nu_cli_args = parse_commandline_args(&nushell_commandline_args, &init_cwd, &mut engine_state); - match nushell_config { - Ok(nushell_config) => { - if let Some(testbin) = &nushell_config.testbin { + match parsed_nu_cli_args { + Ok(binary_args) => { + set_is_perf_value(binary_args.perf); + + if binary_args.perf { + // if we started in perf mode show only the info logs + // TODO: what happens when the config log_level is read? + logger(|builder| { + configure("info", builder)?; + Ok(()) + })?; + info!("start logging {}:{}:{}", file!(), line!(), column!()); + } + + if let Some(testbin) = &binary_args.testbin { // Call out to the correct testbin match testbin.item.as_str() { "echo_env" => test_bins::echo_env(), @@ -133,7 +149,7 @@ fn main() -> Result<()> { } std::process::exit(0) } - let input = if let Some(redirect_stdin) = &nushell_config.redirect_stdin { + let input = if let Some(redirect_stdin) = &binary_args.redirect_stdin { let stdin = std::io::stdin(); let buf_reader = BufReader::new(stdin); @@ -150,18 +166,37 @@ fn main() -> Result<()> { PipelineData::new(Span::new(0, 0)) }; - if let Some(commands) = &nushell_config.commands { - commands::evaluate(commands, &init_cwd, &mut engine_state, input) - } else if !script_name.is_empty() && nushell_config.interactive_shell.is_none() { - eval_file::evaluate( + if is_perf_true() { + info!("redirect_stdin {}:{}:{}", file!(), line!(), column!()); + } + + if let Some(commands) = &binary_args.commands { + let ret_val = commands::evaluate(commands, &init_cwd, &mut engine_state, input); + if is_perf_true() { + info!("-c command execution {}:{}:{}", file!(), line!(), column!()); + } + + ret_val + } else if !script_name.is_empty() && binary_args.interactive_shell.is_none() { + let ret_val = eval_file::evaluate( script_name, &args_to_script, init_cwd, &mut engine_state, input, - ) + ); + if is_perf_true() { + info!("eval_file execution {}:{}:{}", file!(), line!(), column!()); + } + + ret_val } else { - repl::evaluate(&mut engine_state) + let ret_val = repl::evaluate(&mut engine_state); + if is_perf_true() { + info!("repl eval {}:{}:{}", file!(), line!(), column!()); + } + + ret_val } } Err(_) => std::process::exit(1), @@ -172,7 +207,7 @@ fn parse_commandline_args( commandline_args: &str, init_cwd: &Path, engine_state: &mut EngineState, -) -> Result { +) -> Result { let (block, delta) = { let mut working_set = StateWorkingSet::new(engine_state); working_set.add_decl(Box::new(Nu)); @@ -212,6 +247,7 @@ fn parse_commandline_args( let interactive_shell = call.get_named_arg("interactive"); let commands: Option = call.get_flag_expr("commands"); let testbin: Option = call.get_flag_expr("testbin"); + let perf = call.has_flag("perf"); let commands = if let Some(expression) = commands { let contents = engine_state.get_span_contents(&expression.span); @@ -250,12 +286,13 @@ fn parse_commandline_args( std::process::exit(1); } - return Ok(NushellConfig { + return Ok(NushellCliArgs { redirect_stdin, login_shell, interactive_shell, commands, testbin, + perf, }); } } @@ -266,13 +303,14 @@ fn parse_commandline_args( std::process::exit(1); } -struct NushellConfig { +struct NushellCliArgs { redirect_stdin: Option>, #[allow(dead_code)] login_shell: Option>, interactive_shell: Option>, commands: Option>, testbin: Option>, + perf: bool, } #[derive(Clone)] @@ -289,6 +327,11 @@ impl Command for Nu { .switch("stdin", "redirect the stdin", None) .switch("login", "start as a login shell", Some('l')) .switch("interactive", "start as an interactive shell", Some('i')) + .switch( + "perf", + "start and print performance metrics during startup", + Some('p'), + ) .named( "testbin", SyntaxShape::String, @@ -347,3 +390,18 @@ impl Command for Nu { ] } } + +pub fn is_perf_true() -> bool { + IS_PERF.with(|value| *value.borrow()) +} + +// #[allow(dead_code)] +// fn is_perf_value() -> bool { +// IS_PERF.with(|value| *value.borrow()) +// } + +fn set_is_perf_value(value: bool) { + IS_PERF.with(|new_value| { + *new_value.borrow_mut() = value; + }); +} diff --git a/src/prompt_update.rs b/src/prompt_update.rs index 472d10c66..522e7ee18 100644 --- a/src/prompt_update.rs +++ b/src/prompt_update.rs @@ -1,3 +1,5 @@ +use crate::is_perf_true; +use log::info; use nu_cli::NushellPrompt; use nu_engine::eval_subexpression; use nu_parser::parse; @@ -40,6 +42,15 @@ pub(crate) fn get_prompt_indicators( None => "::: ".to_string(), }; + if is_perf_true() { + info!( + "get_prompt_indicators {}:{}:{}", + file!(), + line!(), + column!() + ); + } + ( prompt_indicator, prompt_vi_insert, @@ -60,25 +71,45 @@ fn get_prompt_string( Value::Block { val: block_id, .. } => { let block = engine_state.get_block(block_id); // Use eval_subexpression to force a redirection of output, so we can use everything in prompt - eval_subexpression( + let ret_val = eval_subexpression( engine_state, stack, block, PipelineData::new(Span::new(0, 0)), // Don't try this at home, 0 span is ignored ) - .ok() + .ok(); + if is_perf_true() { + info!( + "get_prompt_string (block) {}:{}:{}", + file!(), + line!(), + column!() + ); + } + + ret_val } Value::String { val: source, .. } => { let mut working_set = StateWorkingSet::new(engine_state); let (block, _) = parse(&mut working_set, None, source.as_bytes(), true); // Use eval_subexpression to force a redirection of output, so we can use everything in prompt - eval_subexpression( + let ret_val = eval_subexpression( engine_state, stack, &block, PipelineData::new(Span::new(0, 0)), // Don't try this at home, 0 span is ignored ) - .ok() + .ok(); + if is_perf_true() { + info!( + "get_prompt_string (string) {}:{}:{}", + file!(), + line!(), + column!() + ); + } + + ret_val } _ => None, }) @@ -127,5 +158,10 @@ pub(crate) fn update_prompt<'prompt>( (prompt_vi_insert_string, prompt_vi_normal_string), ); - nu_prompt as &dyn Prompt + let ret_val = nu_prompt as &dyn Prompt; + if is_perf_true() { + info!("update_prompt {}:{}:{}", file!(), line!(), column!()); + } + + ret_val } diff --git a/src/reedline_config.rs b/src/reedline_config.rs index 8fac3046b..135377467 100644 --- a/src/reedline_config.rs +++ b/src/reedline_config.rs @@ -1,4 +1,6 @@ +use crate::is_perf_true; use crossterm::event::{KeyCode, KeyModifiers}; +use log::info; use nu_color_config::lookup_ansi_color_style; use nu_protocol::{extract_value, Config, ParsedKeybinding, ShellError, Span, Type, Value}; use reedline::{ @@ -64,7 +66,12 @@ pub(crate) fn add_completion_menu(line_editor: Reedline, config: &Config) -> Ree None => completion_menu, }; - line_editor.with_menu(Box::new(completion_menu)) + let ret_val = line_editor.with_menu(Box::new(completion_menu)); + if is_perf_true() { + info!("add_completion_menu {}:{}:{}", file!(), line!(), column!()); + } + + ret_val } // Creates an input object for the history menu based on the dictionary @@ -120,7 +127,12 @@ pub(crate) fn add_history_menu(line_editor: Reedline, config: &Config) -> Reedli None => history_menu, }; - line_editor.with_menu(Box::new(history_menu)) + let ret_val = line_editor.with_menu(Box::new(history_menu)); + if is_perf_true() { + info!("add_history_menu {}:{}:{}", file!(), line!(), column!()); + } + + ret_val } fn add_menu_keybindings(keybindings: &mut Keybindings) { @@ -153,6 +165,10 @@ fn add_menu_keybindings(keybindings: &mut Keybindings) { KeyCode::BackTab, ReedlineEvent::MenuPrevious, ); + + if is_perf_true() { + info!("add_menu_keybindings {}:{}:{}", file!(), line!(), column!()); + } } pub enum KeybindingsMode { @@ -186,6 +202,15 @@ pub(crate) fn create_keybindings(config: &Config) -> Result { @@ -203,6 +228,15 @@ pub(crate) fn create_keybindings(config: &Config) -> Result Result { @@ -381,6 +423,10 @@ fn parse_event(value: Value, config: &Config) -> Result, ShellError>>()?; + if is_perf_true() { + info!("parse_event (list) {}:{}:{}", file!(), line!(), column!()); + } + if until_found { Ok(ReedlineEvent::UntilFound(events)) } else { diff --git a/src/repl.rs b/src/repl.rs index ccd406926..0cf81307d 100644 --- a/src/repl.rs +++ b/src/repl.rs @@ -1,11 +1,11 @@ -use std::{sync::atomic::Ordering, time::Instant}; - +use crate::is_perf_true; use crate::reedline_config::{add_completion_menu, add_history_menu}; use crate::{config_files, prompt_update, reedline_config}; use crate::{ reedline_config::KeybindingsMode, utils::{eval_source, gather_parent_env_vars, report_error}, }; +use log::info; use log::trace; use miette::{IntoDiagnostic, Result}; use nu_cli::{NuCompleter, NuHighlighter, NuValidator, NushellPrompt}; @@ -17,9 +17,10 @@ use nu_protocol::{ Config, ShellError, Span, Value, CONFIG_VARIABLE_ID, }; use reedline::{DefaultHinter, Emacs, Vi}; +use std::{sync::atomic::Ordering, time::Instant}; pub(crate) fn evaluate(engine_state: &mut EngineState) -> Result<()> { - use crate::logger::{configure, logger}; + // use crate::logger::{configure, logger}; use reedline::{FileBackedHistory, Reedline, Signal}; let mut entry_num = 0; @@ -57,13 +58,13 @@ pub(crate) fn evaluate(engine_state: &mut EngineState) -> Result<()> { } }; - logger(|builder| { - configure(&config.log_level, builder)?; - // trace_filters(self, builder)?; - // debug_filters(self, builder)?; + // logger(|builder| { + // configure(&config.log_level, builder)?; + // // trace_filters(self, builder)?; + // // debug_filters(self, builder)?; - Ok(()) - })?; + // Ok(()) + // })?; // Translate environment variables from Strings to Values if let Some(e) = convert_env_values(engine_state, &stack, &config) { @@ -162,8 +163,21 @@ pub(crate) fn evaluate(engine_state: &mut EngineState) -> Result<()> { } }; + if is_perf_true() { + info!("setup line editor {}:{}:{}", file!(), line!(), column!()); + } + let prompt = prompt_update::update_prompt(&config, engine_state, &stack, &mut nu_prompt); + if is_perf_true() { + info!( + "finished prompt update {}:{}:{}", + file!(), + line!(), + column!() + ); + } + entry_num += 1; let input = line_editor.read_line(prompt);