better logging for shell_integration ansi escapes + better plugin perf logging (#12494)

# Description

This PR just adds better logging for shell_integration and tweaks the
ansi escapes so they're closer to where the action happens. I also added
some perf log entries to help better understand plugin file load and
eval performance.

# 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-12 11:11:41 -04:00 committed by GitHub
parent b9c2f9ee56
commit de41345bf2
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
2 changed files with 63 additions and 17 deletions

View file

@ -24,17 +24,35 @@ pub fn read_plugin_file(
plugin_file: Option<Spanned<String>>,
storage_path: &str,
) {
let start_time = std::time::Instant::now();
let mut plug_path = String::new();
let mut start_time = std::time::Instant::now();
// 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);
perf(
"add plugin file to engine_state",
start_time,
file!(),
line!(),
column!(),
engine_state.get_config().use_ansi_coloring,
);
start_time = std::time::Instant::now();
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();
let plug_path = plugin_filename.to_string();
if let Ok(contents) = std::fs::read(&plugin_path) {
perf(
&format!("read plugin file {}", &plug_path),
start_time,
file!(),
line!(),
column!(),
engine_state.get_config().use_ansi_coloring,
);
start_time = std::time::Instant::now();
eval_source(
engine_state,
stack,
@ -43,17 +61,16 @@ pub fn read_plugin_file(
PipelineData::empty(),
false,
);
perf(
&format!("eval_source plugin file {}", &plug_path),
start_time,
file!(),
line!(),
column!(),
engine_state.get_config().use_ansi_coloring,
);
}
}
perf(
&format!("read_plugin_file {}", &plug_path),
start_time,
file!(),
line!(),
column!(),
engine_state.get_config().use_ansi_coloring,
);
}
#[cfg(feature = "plugin")]

View file

@ -573,7 +573,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
run_ansi_sequence(PRE_EXECUTE_MARKER);
perf(
"pre_execute_marker ansi escape sequence",
"pre_execute_marker (133;C) ansi escape sequence",
start_time,
file!(),
line!(),
@ -583,12 +583,27 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
}
// Actual command execution logic starts from here
start_time = Instant::now();
let cmd_execution_start_time = Instant::now();
match parse_operation(s.clone(), engine_state, &stack) {
Ok(operation) => match operation {
ReplOperation::AutoCd { cwd, target, span } => {
do_auto_cd(target, cwd, &mut stack, engine_state, span);
if shell_integration {
start_time = Instant::now();
run_ansi_sequence(&get_command_finished_marker(&stack, engine_state));
perf(
"post_execute_marker (133;D) ansi escape sequences",
start_time,
file!(),
line!(),
column!(),
use_color,
);
}
}
ReplOperation::RunCommand(cmd) => {
line_editor = do_run_cmd(
@ -599,14 +614,29 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
shell_integration,
*entry_num,
use_color,
)
);
if shell_integration {
start_time = Instant::now();
run_ansi_sequence(&get_command_finished_marker(&stack, engine_state));
perf(
"post_execute_marker (133;D) ansi escape sequences",
start_time,
file!(),
line!(),
column!(),
use_color,
);
}
}
// as the name implies, we do nothing in this case
ReplOperation::DoNothing => {}
},
Err(ref e) => error!("Error parsing operation: {e}"),
}
let cmd_duration = start_time.elapsed();
let cmd_duration = cmd_execution_start_time.elapsed();
stack.add_env_var(
"CMD_DURATION_MS".into(),
@ -991,7 +1021,6 @@ fn do_shell_integration_finalize_command(
engine_state: &EngineState,
stack: &mut Stack,
) {
run_ansi_sequence(&get_command_finished_marker(stack, engine_state));
if let Some(cwd) = stack.get_env_var(engine_state, "PWD") {
match cwd.coerce_into_string() {
Ok(path) => {