add a few more logging statements for debugging startup (#12316)

# Description

This PR adds a few more `trace!()` and `perf()` statements that allowed
a deeper understanding of the nushell startup process when used with `nu
-n --no-std-lib --log-level trace`.

# User-Facing Changes
<!-- List of all changes that impact the user experience here. This
helps us keep track of breaking 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` to
check that you're using the standard code style
- `cargo test --workspace` to check that all tests pass (on Windows make
sure to [enable developer
mode](https://learn.microsoft.com/en-us/windows/apps/get-started/developer-mode-features-and-debugging))
- `cargo run -- -c "use std testing; testing run-tests --path
crates/nu-std"` to run the tests for the standard library

> **Note**
> from `nushell` you can also use the `toolkit` as follows
> ```bash
> use toolkit.nu # or use an `env_change` hook to activate it
automatically
> toolkit check pr
> ```
-->

# 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

@@ -3108,6 +3108,7 @@ dependencies = [
 name = "nu-std"
 version = "0.91.1"
 dependencies = [
+ "log",
  "miette",
  "nu-engine",
  "nu-parser",

crates/nu-cli/src/reedline_config.rs

@@ -1,5 +1,6 @@
 use crate::{menus::NuMenuCompleter, NuHelpCompleter};
 use crossterm::event::{KeyCode, KeyModifiers};
+use log::trace;
 use nu_color_config::{color_record_to_nustyle, lookup_ansi_color_style};
 use nu_engine::eval_block;
 use nu_parser::parse;
@@ -78,6 +79,7 @@ pub(crate) fn add_menus(
     stack: &Stack,
     config: &Config,
 ) -> Result<Reedline, ShellError> {
+    trace!("add_menus: config: {:#?}", &config);
     line_editor = line_editor.clear_menus();
 
     for menu in &config.menus {

crates/nu-cli/src/repl.rs

@@ -360,6 +360,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
     );
 
     start_time = std::time::Instant::now();
+    trace!("adding menus");
     line_editor =
         add_menus(line_editor, engine_reference, &stack_arc, config).unwrap_or_else(|e| {
             report_error_new(engine_state, &e);

crates/nu-std/Cargo.toml

@@ -13,3 +13,4 @@ nu-protocol = { version = "0.91.1", path = "../nu-protocol" }
 nu-engine = { version = "0.91.1", path = "../nu-engine" }
 miette = { workspace = true, features = ["fancy-no-backtrace"] }
 
+log = "0.4"

crates/nu-std/src/lib.rs

@@ -1,3 +1,4 @@
+use log::trace;
 use nu_engine::{env::current_dir, eval_block};
 use nu_parser::parse;
 use nu_protocol::{
@@ -13,6 +14,7 @@ const NU_STDLIB_VIRTUAL_DIR: &str = "NU_STDLIB_VIRTUAL_DIR";
 pub fn load_standard_library(
     engine_state: &mut nu_protocol::engine::EngineState,
 ) -> Result<(), miette::ErrReport> {
+    trace!("load_standard_library");
     let (block, delta) = {
         // Using full virtual path to avoid potential conflicts with user having 'std' directory
         // in their working directory.

src/config_files.rs

@@ -1,4 +1,4 @@
-use log::info;
+use log::{info, trace};
 #[cfg(feature = "plugin")]
 use nu_cli::read_plugin_file;
 use nu_cli::{eval_config_contents, eval_source};
@@ -27,6 +27,7 @@ pub(crate) fn read_config_file(
     config_file: Option<Spanned<String>>,
     is_env_config: bool,
 ) {
+    trace!("read_config_file {:?}", &config_file);
     // Load config startup file
     if let Some(file) = config_file {
         let working_set = StateWorkingSet::new(engine_state);
@@ -129,6 +130,7 @@ pub(crate) fn read_loginshell_file(engine_state: &mut EngineState, stack: &mut S
 }
 
 pub(crate) fn read_default_env_file(engine_state: &mut EngineState, stack: &mut Stack) {
+    trace!("read_default_env_file");
     let config_file = get_default_env();
     eval_source(
         engine_state,
@@ -161,6 +163,11 @@ fn eval_default_config(
     config_file: &str,
     is_env_config: bool,
 ) {
+    trace!(
+        "eval_default_config: config_file: {:?}, is_env_config: {}",
+        &config_file,
+        is_env_config
+    );
     println!("Continuing without config file");
     // Just use the contents of "default_config.nu" or "default_env.nu"
     eval_source(
@@ -199,6 +206,12 @@ pub(crate) fn setup_config(
     env_file: Option<Spanned<String>>,
     is_login_shell: bool,
 ) {
+    trace!(
+        "setup_config: config: {:?}, env: {:?}, login: {}",
+        &config_file,
+        &env_file,
+        is_login_shell
+    );
     let result = catch_unwind(AssertUnwindSafe(|| {
         #[cfg(feature = "plugin")]
         read_plugin_file(engine_state, stack, plugin_file, NUSHELL_FOLDER);
@@ -225,6 +238,13 @@ pub(crate) fn set_config_path(
     key: &str,
     config_file: Option<&Spanned<String>>,
 ) {
+    trace!(
+        "set_config_path: cwd: {:?}, default_config: {}, key: {}, config_file: {:?}",
+        &cwd,
+        &default_config_name,
+        &key,
+        &config_file
+    );
     let config_path = match config_file {
         Some(s) => canonicalize_with(&s.item, cwd).ok(),
         None => nu_path::config_dir().map(|mut p| {

src/main.rs

@@ -20,7 +20,7 @@ use crate::{
     logger::{configure, logger},
 };
 use command::gather_commandline_args;
-use log::Level;
+use log::{trace, Level};
 use miette::Result;
 use nu_cli::gather_parent_env_vars;
 use nu_cmd_base::util::get_init_cwd;
@@ -233,6 +233,7 @@ fn main() -> Result<()> {
         );
     }
 
+    start_time = std::time::Instant::now();
     if let Some(include_path) = &parsed_nu_cli_args.include_path {
         let span = include_path.span;
         let vals: Vec<_> = include_path
@@ -243,6 +244,14 @@ fn main() -> Result<()> {
 
         engine_state.add_env_var("NU_LIB_DIRS".into(), Value::list(vals, span));
     }
+    perf(
+        "NU_LIB_DIRS setup",
+        start_time,
+        file!(),
+        line!(),
+        column!(),
+        use_color,
+    );
 
     start_time = std::time::Instant::now();
     // First, set up env vars as strings only
@@ -265,7 +274,16 @@ fn main() -> Result<()> {
         load_standard_library(&mut engine_state)?;
     }
 
+    start_time = std::time::Instant::now();
     if parsed_nu_cli_args.lsp {
+        perf(
+            "lsp starting",
+            start_time,
+            file!(),
+            line!(),
+            column!(),
+            use_color,
+        );
         return LanguageServer::initialize_stdio_connection()?.serve_requests(engine_state, ctrlc);
     }
 
@@ -330,6 +348,7 @@ fn main() -> Result<()> {
 
     start_time = std::time::Instant::now();
     let input = if let Some(redirect_stdin) = &parsed_nu_cli_args.redirect_stdin {
+        trace!("redirecting stdin");
         let stdin = std::io::stdin();
         let buf_reader = BufReader::new(stdin);
 
@@ -347,6 +366,7 @@ fn main() -> Result<()> {
             trim_end_newline: false,
         }
     } else {
+        trace!("not redirecting stdin");
         PipelineData::empty()
     };
     perf(
@@ -358,9 +378,18 @@ fn main() -> Result<()> {
         use_color,
     );
 
+    start_time = std::time::Instant::now();
     // Set up the $nu constant before evaluating config files (need to have $nu available in them)
     let nu_const = create_nu_constant(&engine_state, input.span().unwrap_or_else(Span::unknown))?;
     engine_state.set_variable_const_val(NU_VARIABLE_ID, nu_const);
+    perf(
+        "create_nu_constant",
+        start_time,
+        file!(),
+        line!(),
+        column!(),
+        use_color,
+    );
 
     if let Some(commands) = parsed_nu_cli_args.commands.clone() {
         run_commands(

src/run.rs

@@ -4,6 +4,7 @@ use crate::{
     command,
     config_files::{self, setup_config},
 };
+use log::trace;
 #[cfg(feature = "plugin")]
 use nu_cli::read_plugin_file;
 use nu_cli::{evaluate_commands, evaluate_file, evaluate_repl};
@@ -18,6 +19,7 @@ pub(crate) fn run_commands(
     input: PipelineData,
     entire_start_time: std::time::Instant,
 ) -> Result<(), miette::ErrReport> {
+    trace!("run_commands");
     let mut stack = nu_protocol::engine::Stack::new();
     let start_time = std::time::Instant::now();
 
@@ -141,6 +143,7 @@ pub(crate) fn run_file(
     args_to_script: Vec<String>,
     input: PipelineData,
 ) -> Result<(), miette::ErrReport> {
+    trace!("run_file");
     let mut stack = nu_protocol::engine::Stack::new();
     let start_time = std::time::Instant::now();
 
@@ -242,6 +245,7 @@ pub(crate) fn run_repl(
     parsed_nu_cli_args: command::NushellCliArgs,
     entire_start_time: std::time::Instant,
 ) -> Result<(), miette::ErrReport> {
+    trace!("run_repl");
     let mut stack = nu_protocol::engine::Stack::new();
     let start_time = std::time::Instant::now();