try to be a bit more precise with repl logging (#12449)

# Description

This PR tries to be a bit more precise with the repl logging when
starting nushell with `nu --log-level debug`. It adds a few more `perf`
lines and changes some of the text of others.

# 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.
-->
This commit is contained in:
Darren Schroeder 2024-04-08 06:36:54 -04:00 committed by GitHub
parent 56c9587cc3
commit 40f72e80c3
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194

View File

@ -364,6 +364,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
.with_partial_completions(config.partial_completions) .with_partial_completions(config.partial_completions)
.with_ansi_colors(config.use_ansi_coloring) .with_ansi_colors(config.use_ansi_coloring)
.with_cursor_config(cursor_config); .with_cursor_config(cursor_config);
perf( perf(
"reedline builder", "reedline builder",
start_time, start_time,
@ -385,6 +386,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
} else { } else {
line_editor.disable_hints() line_editor.disable_hints()
}; };
perf( perf(
"reedline coloring/style_computer", "reedline coloring/style_computer",
start_time, start_time,
@ -401,8 +403,9 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
report_error_new(engine_state, &e); report_error_new(engine_state, &e);
Reedline::create() Reedline::create()
}); });
perf( perf(
"reedline menus", "reedline adding menus",
start_time, start_time,
file!(), file!(),
line!(), line!(),
@ -424,6 +427,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
} else { } else {
line_editor line_editor
}; };
perf( perf(
"reedline buffer_editor", "reedline buffer_editor",
start_time, start_time,
@ -440,6 +444,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
warn!("Failed to sync history: {}", e); warn!("Failed to sync history: {}", e);
} }
} }
perf( perf(
"sync_history", "sync_history",
start_time, start_time,
@ -453,6 +458,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
// Changing the line editor based on the found keybindings // Changing the line editor based on the found keybindings
line_editor = setup_keybindings(engine_state, line_editor); line_editor = setup_keybindings(engine_state, line_editor);
perf( perf(
"keybindings", "keybindings",
start_time, start_time,
@ -476,6 +482,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
&mut Stack::with_parent(stack_arc.clone()), &mut Stack::with_parent(stack_arc.clone()),
nu_prompt, nu_prompt,
); );
perf( perf(
"update_prompt", "update_prompt",
start_time, start_time,
@ -501,6 +508,16 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
let mut stack = Stack::unwrap_unique(stack_arc); let mut stack = Stack::unwrap_unique(stack_arc);
perf(
"line_editor setup",
start_time,
file!(),
line!(),
column!(),
use_color,
);
let line_editor_input_time = std::time::Instant::now();
match input { match input {
Ok(Signal::Success(s)) => { Ok(Signal::Success(s)) => {
let hostname = System::host_name(); let hostname = System::host_name();
@ -513,6 +530,9 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
prepare_history_metadata(&s, &hostname, engine_state, &mut line_editor); prepare_history_metadata(&s, &hostname, engine_state, &mut line_editor);
} }
// For pre_exec_hook
start_time = Instant::now();
// Right before we start running the code the user gave us, fire the `pre_execution` // Right before we start running the code the user gave us, fire the `pre_execution`
// hook // hook
if let Some(hook) = config.hooks.pre_execution.clone() { if let Some(hook) = config.hooks.pre_execution.clone() {
@ -533,17 +553,37 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
} }
} }
perf(
"pre_execution_hook",
start_time,
file!(),
line!(),
column!(),
use_color,
);
let mut repl = engine_state.repl_state.lock().expect("repl state mutex"); let mut repl = engine_state.repl_state.lock().expect("repl state mutex");
repl.cursor_pos = line_editor.current_insertion_point(); repl.cursor_pos = line_editor.current_insertion_point();
repl.buffer = line_editor.current_buffer_contents().to_string(); repl.buffer = line_editor.current_buffer_contents().to_string();
drop(repl); drop(repl);
if shell_integration { if shell_integration {
start_time = Instant::now();
run_ansi_sequence(PRE_EXECUTE_MARKER); run_ansi_sequence(PRE_EXECUTE_MARKER);
perf(
"pre_execute_marker ansi escape sequence",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
// Actual command execution logic starts from here // Actual command execution logic starts from here
let start_time = Instant::now(); start_time = Instant::now();
match parse_operation(s.clone(), engine_state, &stack) { match parse_operation(s.clone(), engine_state, &stack) {
Ok(operation) => match operation { Ok(operation) => match operation {
@ -558,6 +598,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
line_editor, line_editor,
shell_integration, shell_integration,
*entry_num, *entry_num,
use_color,
) )
} }
// as the name implies, we do nothing in this case // as the name implies, we do nothing in this case
@ -585,7 +626,18 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
} }
if shell_integration { if shell_integration {
start_time = Instant::now();
do_shell_integration_finalize_command(hostname, engine_state, &mut stack); do_shell_integration_finalize_command(hostname, engine_state, &mut stack);
perf(
"shell_integration_finalize ansi escape sequences",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
flush_engine_state_repl_buffer(engine_state, &mut line_editor); flush_engine_state_repl_buffer(engine_state, &mut line_editor);
@ -593,13 +645,35 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
Ok(Signal::CtrlC) => { Ok(Signal::CtrlC) => {
// `Reedline` clears the line content. New prompt is shown // `Reedline` clears the line content. New prompt is shown
if shell_integration { if shell_integration {
start_time = Instant::now();
run_ansi_sequence(&get_command_finished_marker(&stack, engine_state)); run_ansi_sequence(&get_command_finished_marker(&stack, engine_state));
perf(
"command_finished_marker ansi escape sequence",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
} }
Ok(Signal::CtrlD) => { Ok(Signal::CtrlD) => {
// When exiting clear to a new line // When exiting clear to a new line
if shell_integration { if shell_integration {
start_time = Instant::now();
run_ansi_sequence(&get_command_finished_marker(&stack, engine_state)); run_ansi_sequence(&get_command_finished_marker(&stack, engine_state));
perf(
"command_finished_marker ansi escape sequence",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
println!(); println!();
return (false, stack, line_editor); return (false, stack, line_editor);
@ -614,13 +688,24 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
// Alternatively only allow that expected failures let the REPL loop // Alternatively only allow that expected failures let the REPL loop
} }
if shell_integration { if shell_integration {
start_time = Instant::now();
run_ansi_sequence(&get_command_finished_marker(&stack, engine_state)); run_ansi_sequence(&get_command_finished_marker(&stack, engine_state));
perf(
"command_finished_marker ansi escape sequence",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
} }
} }
perf( perf(
"processing line editor input", "processing line editor input",
start_time, line_editor_input_time,
file!(), file!(),
line!(), line!(),
column!(), column!(),
@ -628,7 +713,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
); );
perf( perf(
"finished repl loop", "time between prompts in line editor loop",
loop_start_time, loop_start_time,
file!(), file!(),
line!(), line!(),
@ -825,6 +910,7 @@ fn do_run_cmd(
line_editor: Reedline, line_editor: Reedline,
shell_integration: bool, shell_integration: bool,
entry_num: usize, entry_num: usize,
use_color: bool,
) -> Reedline { ) -> Reedline {
trace!("eval source: {}", s); trace!("eval source: {}", s);
@ -850,6 +936,7 @@ fn do_run_cmd(
} }
if shell_integration { if shell_integration {
let start_time = Instant::now();
if let Some(cwd) = stack.get_env_var(engine_state, "PWD") { if let Some(cwd) = stack.get_env_var(engine_state, "PWD") {
match cwd.coerce_into_string() { match cwd.coerce_into_string() {
Ok(path) => { Ok(path) => {
@ -872,6 +959,15 @@ fn do_run_cmd(
} }
} }
} }
perf(
"set title with command ansi escape sequence",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
eval_source( eval_source(