Converted perf function to be a macro. Utilized the perf macro within the polars plugin. (#13224)

In this pull request, I converted the `perf` function within `nu_utils`
to a macro. This change facilitates easier usage within plugins by
allowing the use of `env_logger` and setting `RUST_LOG=nu_plugin_polars`
(or another plugin). Without this conversion, the `RUST_LOG` variable
would need to be set to `RUST_LOG=nu_utils::utils`, which is less
intuitive and impossible to narrow the perf results to one plugin.
This commit is contained in:
Jack Wright 2024-06-27 16:56:56 -07:00 committed by GitHub
parent 0d79b63711
commit 1f1f581357
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
12 changed files with 154 additions and 524 deletions

34
Cargo.lock generated
View File

@ -1330,6 +1330,16 @@ dependencies = [
"syn 2.0.60", "syn 2.0.60",
] ]
[[package]]
name = "env_filter"
version = "0.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "a009aa4810eb158359dda09d0c87378e4bbb89b5a801f016885a4707ba24f7ea"
dependencies = [
"log",
"regex",
]
[[package]] [[package]]
name = "env_logger" name = "env_logger"
version = "0.8.4" version = "0.8.4"
@ -1340,6 +1350,19 @@ dependencies = [
"regex", "regex",
] ]
[[package]]
name = "env_logger"
version = "0.11.3"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "38b35839ba51819680ba087cd351788c9a3c476841207e0b8cee0b04722343b9"
dependencies = [
"anstream",
"anstyle",
"env_filter",
"humantime",
"log",
]
[[package]] [[package]]
name = "equivalent" name = "equivalent"
version = "1.0.1" version = "1.0.1"
@ -1906,6 +1929,12 @@ dependencies = [
"thiserror", "thiserror",
] ]
[[package]]
name = "humantime"
version = "2.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4"
[[package]] [[package]]
name = "hyper" name = "hyper"
version = "0.14.28" version = "0.14.28"
@ -3391,8 +3420,10 @@ version = "0.95.1"
dependencies = [ dependencies = [
"chrono", "chrono",
"chrono-tz 0.9.0", "chrono-tz 0.9.0",
"env_logger 0.11.3",
"fancy-regex", "fancy-regex",
"indexmap", "indexmap",
"log",
"mimalloc", "mimalloc",
"nu-cmd-lang", "nu-cmd-lang",
"nu-command", "nu-command",
@ -3402,6 +3433,7 @@ dependencies = [
"nu-plugin", "nu-plugin",
"nu-plugin-test-support", "nu-plugin-test-support",
"nu-protocol", "nu-protocol",
"nu-utils",
"num", "num",
"polars", "polars",
"polars-arrow", "polars-arrow",
@ -4667,7 +4699,7 @@ version = "1.0.3"
source = "registry+https://github.com/rust-lang/crates.io-index" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "588f6378e4dd99458b60ec275b4477add41ce4fa9f64dcba6f15adccb19b50d6" checksum = "588f6378e4dd99458b60ec275b4477add41ce4fa9f64dcba6f15adccb19b50d6"
dependencies = [ dependencies = [
"env_logger", "env_logger 0.8.4",
"log", "log",
"rand", "rand",
] ]

View File

@ -8,7 +8,7 @@ use nu_protocol::{
report_error_new, HistoryFileFormat, PipelineData, report_error_new, HistoryFileFormat, PipelineData,
}; };
#[cfg(feature = "plugin")] #[cfg(feature = "plugin")]
use nu_utils::utils::perf; use nu_utils::perf;
use std::path::PathBuf; use std::path::PathBuf;
#[cfg(feature = "plugin")] #[cfg(feature = "plugin")]
@ -53,13 +53,10 @@ pub fn read_plugin_file(
// Reading signatures from plugin registry file // Reading signatures from plugin registry file
// The plugin.msgpackz file stores the parsed signature collected from each registered plugin // The plugin.msgpackz file stores the parsed signature collected from each registered plugin
add_plugin_file(engine_state, plugin_file.clone(), storage_path); add_plugin_file(engine_state, plugin_file.clone(), storage_path);
perf( perf!(
"add plugin file to engine_state", "add plugin file to engine_state",
start_time, start_time,
file!(), engine_state.get_config().use_ansi_coloring
line!(),
column!(),
engine_state.get_config().use_ansi_coloring,
); );
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
@ -137,13 +134,10 @@ pub fn read_plugin_file(
} }
}; };
perf( perf!(
&format!("read plugin file {}", plugin_path.display()), &format!("read plugin file {}", plugin_path.display()),
start_time, start_time,
file!(), engine_state.get_config().use_ansi_coloring
line!(),
column!(),
engine_state.get_config().use_ansi_coloring,
); );
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
@ -156,13 +150,10 @@ pub fn read_plugin_file(
return; return;
} }
perf( perf!(
&format!("load plugin file {}", plugin_path.display()), &format!("load plugin file {}", plugin_path.display()),
start_time, start_time,
file!(), engine_state.get_config().use_ansi_coloring
line!(),
column!(),
engine_state.get_config().use_ansi_coloring,
); );
} }
} }
@ -381,13 +372,10 @@ pub fn migrate_old_plugin_file(engine_state: &EngineState, storage_path: &str) -
); );
} }
perf( perf!(
"migrate old plugin file", "migrate old plugin file",
start_time, start_time,
file!(), engine_state.get_config().use_ansi_coloring
line!(),
column!(),
engine_state.get_config().use_ansi_coloring,
); );
true true
} }

View File

@ -31,7 +31,7 @@ use nu_protocol::{
}; };
use nu_utils::{ use nu_utils::{
filesystem::{have_permission, PermissionResult}, filesystem::{have_permission, PermissionResult},
utils::perf, perf,
}; };
use reedline::{ use reedline::{
CursorConfig, CwdAwareHinter, DefaultCompleter, EditCommand, Emacs, FileBackedHistory, CursorConfig, CwdAwareHinter, DefaultCompleter, EditCommand, Emacs, FileBackedHistory,
@ -89,14 +89,7 @@ pub fn evaluate_repl(
if let Err(e) = convert_env_values(engine_state, &unique_stack) { if let Err(e) = convert_env_values(engine_state, &unique_stack) {
report_error_new(engine_state, &e); report_error_new(engine_state, &e);
} }
perf( perf!("translate env vars", start_time, use_color);
"translate env vars",
start_time,
file!(),
line!(),
column!(),
use_color,
);
// seed env vars // seed env vars
unique_stack.add_env_var( unique_stack.add_env_var(
@ -225,28 +218,14 @@ fn get_line_editor(
// Now that reedline is created, get the history session id and store it in engine_state // Now that reedline is created, get the history session id and store it in engine_state
store_history_id_in_engine(engine_state, &line_editor); store_history_id_in_engine(engine_state, &line_editor);
perf( perf!("setup reedline", start_time, use_color);
"setup reedline",
start_time,
file!(),
line!(),
column!(),
use_color,
);
if let Some(history) = engine_state.history_config() { if let Some(history) = engine_state.history_config() {
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
line_editor = setup_history(nushell_path, engine_state, line_editor, history)?; line_editor = setup_history(nushell_path, engine_state, line_editor, history)?;
perf( perf!("setup history", start_time, use_color);
"setup history",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
Ok(line_editor) Ok(line_editor)
} }
@ -289,28 +268,14 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
if let Err(err) = engine_state.merge_env(&mut stack, cwd) { if let Err(err) = engine_state.merge_env(&mut stack, cwd) {
report_error_new(engine_state, &err); report_error_new(engine_state, &err);
} }
perf( perf!("merge env", start_time, use_color);
"merge env",
start_time,
file!(),
line!(),
column!(),
use_color,
);
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
// Reset the ctrl-c handler // Reset the ctrl-c handler
if let Some(ctrlc) = &mut engine_state.ctrlc { if let Some(ctrlc) = &mut engine_state.ctrlc {
ctrlc.store(false, Ordering::SeqCst); ctrlc.store(false, Ordering::SeqCst);
} }
perf( perf!("reset ctrlc", start_time, use_color);
"reset ctrlc",
start_time,
file!(),
line!(),
column!(),
use_color,
);
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
// Right before we start our prompt and take input from the user, // Right before we start our prompt and take input from the user,
@ -320,14 +285,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
report_error_new(engine_state, &err); report_error_new(engine_state, &err);
} }
} }
perf( perf!("pre-prompt hook", start_time, use_color);
"pre-prompt hook",
start_time,
file!(),
line!(),
column!(),
use_color,
);
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
// Next, check all the environment variables they ask for // Next, check all the environment variables they ask for
@ -336,14 +294,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
if let Err(error) = hook::eval_env_change_hook(env_change, engine_state, &mut stack) { if let Err(error) = hook::eval_env_change_hook(env_change, engine_state, &mut stack) {
report_error_new(engine_state, &error) report_error_new(engine_state, &error)
} }
perf( perf!("env-change hook", start_time, use_color);
"env-change hook",
start_time,
file!(),
line!(),
column!(),
use_color,
);
let engine_reference = Arc::new(engine_state.clone()); let engine_reference = Arc::new(engine_state.clone());
let config = engine_state.get_config(); let config = engine_state.get_config();
@ -355,14 +306,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
vi_normal: map_nucursorshape_to_cursorshape(config.cursor_shape_vi_normal), vi_normal: map_nucursorshape_to_cursorshape(config.cursor_shape_vi_normal),
emacs: map_nucursorshape_to_cursorshape(config.cursor_shape_emacs), emacs: map_nucursorshape_to_cursorshape(config.cursor_shape_emacs),
}; };
perf( perf!("get config/cursor config", start_time, use_color);
"get config/cursor config",
start_time,
file!(),
line!(),
column!(),
use_color,
);
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
// at this line we have cloned the state for the completer and the transient prompt // at this line we have cloned the state for the completer and the transient prompt
@ -394,14 +338,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
.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", start_time, use_color);
"reedline builder",
start_time,
file!(),
line!(),
column!(),
use_color,
);
let style_computer = StyleComputer::from_config(engine_state, &stack_arc); let style_computer = StyleComputer::from_config(engine_state, &stack_arc);
@ -416,14 +353,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
line_editor.disable_hints() line_editor.disable_hints()
}; };
perf( perf!("reedline coloring/style_computer", start_time, use_color);
"reedline coloring/style_computer",
start_time,
file!(),
line!(),
column!(),
use_color,
);
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
trace!("adding menus"); trace!("adding menus");
@ -433,14 +363,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
Reedline::create() Reedline::create()
}); });
perf( perf!("reedline adding menus", start_time, use_color);
"reedline adding menus",
start_time,
file!(),
line!(),
column!(),
use_color,
);
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
let buffer_editor = get_editor(engine_state, &stack_arc, Span::unknown()); let buffer_editor = get_editor(engine_state, &stack_arc, Span::unknown());
@ -457,14 +380,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
line_editor line_editor
}; };
perf( perf!("reedline buffer_editor", start_time, use_color);
"reedline buffer_editor",
start_time,
file!(),
line!(),
column!(),
use_color,
);
if let Some(history) = engine_state.history_config() { if let Some(history) = engine_state.history_config() {
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
@ -474,28 +390,14 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
} }
} }
perf( perf!("sync_history", start_time, use_color);
"sync_history",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
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", start_time, use_color);
"keybindings",
start_time,
file!(),
line!(),
column!(),
use_color,
);
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
let config = &engine_state.get_config().clone(); let config = &engine_state.get_config().clone();
@ -512,14 +414,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
nu_prompt, nu_prompt,
); );
perf( perf!("update_prompt", start_time, use_color);
"update_prompt",
start_time,
file!(),
line!(),
column!(),
use_color,
);
*entry_num += 1; *entry_num += 1;
@ -546,14 +441,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
// so we should avoid it or making stack cheaper to clone. // so we should avoid it or making stack cheaper to clone.
let mut stack = Arc::unwrap_or_clone(stack_arc); let mut stack = Arc::unwrap_or_clone(stack_arc);
perf( perf!("line_editor setup", start_time, use_color);
"line_editor setup",
start_time,
file!(),
line!(),
column!(),
use_color,
);
let line_editor_input_time = std::time::Instant::now(); let line_editor_input_time = std::time::Instant::now();
match input { match input {
@ -590,14 +478,7 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
} }
} }
perf( perf!("pre_execution_hook", start_time, use_color);
"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();
@ -612,26 +493,20 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
run_ansi_sequence(VSCODE_PRE_EXECUTION_MARKER); run_ansi_sequence(VSCODE_PRE_EXECUTION_MARKER);
perf( perf!(
"pre_execute_marker (633;C) ansi escape sequence", "pre_execute_marker (633;C) ansi escape sequence",
start_time, start_time,
file!(), use_color
line!(),
column!(),
use_color,
); );
} else if shell_integration_osc133 { } else if shell_integration_osc133 {
start_time = Instant::now(); start_time = Instant::now();
run_ansi_sequence(PRE_EXECUTION_MARKER); run_ansi_sequence(PRE_EXECUTION_MARKER);
perf( perf!(
"pre_execute_marker (133;C) ansi escape sequence", "pre_execute_marker (133;C) ansi escape sequence",
start_time, start_time,
file!(), use_color
line!(),
column!(),
use_color,
); );
} }
} else if shell_integration_osc133 { } else if shell_integration_osc133 {
@ -639,13 +514,10 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
run_ansi_sequence(PRE_EXECUTION_MARKER); run_ansi_sequence(PRE_EXECUTION_MARKER);
perf( perf!(
"pre_execute_marker (133;C) ansi escape sequence", "pre_execute_marker (133;C) ansi escape sequence",
start_time, start_time,
file!(), use_color
line!(),
column!(),
use_color,
); );
} }
@ -769,22 +641,16 @@ fn loop_iteration(ctx: LoopContext) -> (bool, Stack, Reedline) {
); );
} }
} }
perf( perf!(
"processing line editor input", "processing line editor input",
line_editor_input_time, line_editor_input_time,
file!(), use_color
line!(),
column!(),
use_color,
); );
perf( perf!(
"time between prompts in line editor loop", "time between prompts in line editor loop",
loop_start_time, loop_start_time,
file!(), use_color
line!(),
column!(),
use_color,
); );
(true, stack, line_editor) (true, stack, line_editor)
@ -1061,14 +927,7 @@ fn run_shell_integration_osc2(
// ESC]2;stringBEL -- Set window title to string // ESC]2;stringBEL -- Set window title to string
run_ansi_sequence(&format!("\x1b]2;{title}\x07")); run_ansi_sequence(&format!("\x1b]2;{title}\x07"));
perf( perf!("set title with command osc2", start_time, use_color);
"set title with command osc2",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
} }
@ -1093,13 +952,10 @@ fn run_shell_integration_osc7(
percent_encoding::utf8_percent_encode(&path, percent_encoding::CONTROLS) percent_encoding::utf8_percent_encode(&path, percent_encoding::CONTROLS)
)); ));
perf( perf!(
"communicate path to terminal with osc7", "communicate path to terminal with osc7",
start_time, start_time,
file!(), use_color
line!(),
column!(),
use_color,
); );
} }
} }
@ -1116,13 +972,10 @@ fn run_shell_integration_osc9_9(engine_state: &EngineState, stack: &mut Stack, u
percent_encoding::utf8_percent_encode(&path, percent_encoding::CONTROLS) percent_encoding::utf8_percent_encode(&path, percent_encoding::CONTROLS)
)); ));
perf( perf!(
"communicate path to terminal with osc9;9", "communicate path to terminal with osc9;9",
start_time, start_time,
file!(), use_color
line!(),
column!(),
use_color,
); );
} }
} }
@ -1142,13 +995,10 @@ fn run_shell_integration_osc633(engine_state: &EngineState, stack: &mut Stack, u
VSCODE_CWD_PROPERTY_MARKER_PREFIX, path, VSCODE_CWD_PROPERTY_MARKER_SUFFIX VSCODE_CWD_PROPERTY_MARKER_PREFIX, path, VSCODE_CWD_PROPERTY_MARKER_SUFFIX
)); ));
perf( perf!(
"communicate path to terminal with osc633;P", "communicate path to terminal with osc633;P",
start_time, start_time,
file!(), use_color
line!(),
column!(),
use_color,
); );
} }
} }
@ -1371,13 +1221,10 @@ fn run_finaliziation_ansi_sequence(
shell_integration_osc133, shell_integration_osc133,
)); ));
perf( perf!(
"post_execute_marker (633;D) ansi escape sequences", "post_execute_marker (633;D) ansi escape sequences",
start_time, start_time,
file!(), use_color
line!(),
column!(),
use_color,
); );
} else if shell_integration_osc133 { } else if shell_integration_osc133 {
let start_time = Instant::now(); let start_time = Instant::now();
@ -1389,13 +1236,10 @@ fn run_finaliziation_ansi_sequence(
shell_integration_osc133, shell_integration_osc133,
)); ));
perf( perf!(
"post_execute_marker (133;D) ansi escape sequences", "post_execute_marker (133;D) ansi escape sequences",
start_time, start_time,
file!(), use_color
line!(),
column!(),
use_color,
); );
} }
} else if shell_integration_osc133 { } else if shell_integration_osc133 {
@ -1408,13 +1252,10 @@ fn run_finaliziation_ansi_sequence(
shell_integration_osc133, shell_integration_osc133,
)); ));
perf( perf!(
"post_execute_marker (133;D) ansi escape sequences", "post_execute_marker (133;D) ansi escape sequences",
start_time, start_time,
file!(), use_color
line!(),
column!(),
use_color,
); );
} }
} }

View File

@ -8,7 +8,7 @@ use nu_protocol::{
}; };
#[cfg(windows)] #[cfg(windows)]
use nu_utils::enable_vt_processing; use nu_utils::enable_vt_processing;
use nu_utils::utils::perf; use nu_utils::perf;
use std::path::Path; use std::path::Path;
// This will collect environment variables from std::env and adds them to a stack. // This will collect environment variables from std::env and adds them to a stack.
@ -228,13 +228,10 @@ pub fn eval_source(
let _ = enable_vt_processing(); let _ = enable_vt_processing();
} }
perf( perf!(
&format!("eval_source {}", &fname), &format!("eval_source {}", &fname),
start_time, start_time,
file!(), engine_state.get_config().use_ansi_coloring
line!(),
column!(),
engine_state.get_config().use_ansi_coloring,
); );
exit_code exit_code

View File

@ -1,4 +1,3 @@
use log::info;
use lscolors::LsColors; use lscolors::LsColors;
use std::io::{Result, Write}; use std::io::{Result, Write};
@ -393,31 +392,27 @@ pub fn get_ls_colors(lscolors_env_string: Option<String>) -> LsColors {
} }
// Log some performance metrics (green text with yellow timings) // Log some performance metrics (green text with yellow timings)
pub fn perf( #[macro_export]
msg: &str, macro_rules! perf {
dur: std::time::Instant, ($msg:expr, $dur:expr, $use_color:expr) => {
file: &str, if $use_color {
line: u32, log::info!(
column: u32,
use_color: bool,
) {
if use_color {
info!(
"perf: {}:{}:{} \x1b[32m{}\x1b[0m took \x1b[33m{:?}\x1b[0m", "perf: {}:{}:{} \x1b[32m{}\x1b[0m took \x1b[33m{:?}\x1b[0m",
file, file!(),
line, line!(),
column, column!(),
msg, $msg,
dur.elapsed(), $dur.elapsed(),
); );
} else { } else {
info!( log::info!(
"perf: {}:{}:{} {} took {:?}", "perf: {}:{}:{} {} took {:?}",
file, file!(),
line, line!(),
column, column!(),
msg, $msg,
dur.elapsed(), $dur.elapsed(),
); );
} }
};
} }

View File

@ -20,6 +20,7 @@ bench = false
nu-protocol = { path = "../nu-protocol", version = "0.95.1" } nu-protocol = { path = "../nu-protocol", version = "0.95.1" }
nu-plugin = { path = "../nu-plugin", version = "0.95.1" } nu-plugin = { path = "../nu-plugin", version = "0.95.1" }
nu-path = { path = "../nu-path", version = "0.95.1" } nu-path = { path = "../nu-path", version = "0.95.1" }
nu-utils = { path = "../nu-utils", version = "0.95.1" }
# Potential dependencies for extras # Potential dependencies for extras
chrono = { workspace = true, features = ["std", "unstable-locales"], default-features = false } chrono = { workspace = true, features = ["std", "unstable-locales"], default-features = false }
@ -36,6 +37,8 @@ polars-ops = { version = "0.40"}
polars-plan = { version = "0.40", features = ["regex"]} polars-plan = { version = "0.40", features = ["regex"]}
polars-utils = { version = "0.40"} polars-utils = { version = "0.40"}
typetag = "0.2" typetag = "0.2"
env_logger = "0.11.3"
log.workspace = true
uuid = { version = "1.9", features = ["v4", "serde"] } uuid = { version = "1.9", features = ["v4", "serde"] }
[dependencies.polars] [dependencies.polars]

View File

@ -13,7 +13,9 @@ use nu_plugin::{EngineInterface, PluginCommand};
use nu_protocol::{LabeledError, ShellError, Span}; use nu_protocol::{LabeledError, ShellError, Span};
use uuid::Uuid; use uuid::Uuid;
use crate::{plugin_debug, values::PolarsPluginObject, EngineWrapper, PolarsPlugin}; use crate::{values::PolarsPluginObject, EngineWrapper, PolarsPlugin};
use log::debug;
#[derive(Debug, Clone)] #[derive(Debug, Clone)]
pub struct CacheValue { pub struct CacheValue {
@ -60,22 +62,16 @@ impl Cache {
let removed = if force || reference_count.unwrap_or_default() < 1 { let removed = if force || reference_count.unwrap_or_default() < 1 {
let removed = lock.remove(key); let removed = lock.remove(key);
plugin_debug!( debug!("PolarsPlugin: removing {key} from cache: {removed:?}");
engine,
"PolarsPlugin: removing {key} from cache: {removed:?}"
);
removed removed
} else { } else {
plugin_debug!( debug!("PolarsPlugin: decrementing reference count for {key}");
engine,
"PolarsPlugin: decrementing reference count for {key}"
);
None None
}; };
// Once there are no more entries in the cache // Once there are no more entries in the cache
// we can turn plugin gc back on // we can turn plugin gc back on
plugin_debug!(engine, "PolarsPlugin: Cache is empty enabling GC"); debug!("PolarsPlugin: Cache is empty enabling GC");
engine.set_gc_disabled(false).map_err(LabeledError::from)?; engine.set_gc_disabled(false).map_err(LabeledError::from)?;
drop(lock); drop(lock);
Ok(removed) Ok(removed)
@ -91,14 +87,11 @@ impl Cache {
span: Span, span: Span,
) -> Result<Option<CacheValue>, ShellError> { ) -> Result<Option<CacheValue>, ShellError> {
let mut lock = self.lock()?; let mut lock = self.lock()?;
plugin_debug!( debug!("PolarsPlugin: Inserting {uuid} into cache: {value:?}");
engine,
"PolarsPlugin: Inserting {uuid} into cache: {value:?}"
);
// turn off plugin gc the first time an entry is added to the cache // turn off plugin gc the first time an entry is added to the cache
// as we don't want the plugin to be garbage collected if there // as we don't want the plugin to be garbage collected if there
// is any live data // is any live data
plugin_debug!(engine, "PolarsPlugin: Cache has values disabling GC"); debug!("PolarsPlugin: Cache has values disabling GC");
engine.set_gc_disabled(true).map_err(LabeledError::from)?; engine.set_gc_disabled(true).map_err(LabeledError::from)?;
let cache_value = CacheValue { let cache_value = CacheValue {
uuid, uuid,

View File

@ -1,10 +1,10 @@
use crate::{ use crate::{
dataframe::values::NuSchema, dataframe::values::NuSchema,
perf,
values::{CustomValueSupport, NuLazyFrame}, values::{CustomValueSupport, NuLazyFrame},
PolarsPlugin, EngineWrapper, PolarsPlugin,
}; };
use nu_path::expand_path_with; use nu_path::expand_path_with;
use nu_utils::perf;
use super::super::values::NuDataFrame; use super::super::values::NuDataFrame;
use nu_plugin::PluginCommand; use nu_plugin::PluginCommand;
@ -399,13 +399,10 @@ fn from_jsonl(
inner: vec![], inner: vec![],
})?; })?;
perf( perf!(
engine,
"Lazy json lines dataframe open", "Lazy json lines dataframe open",
start_time, start_time,
file!(), engine.use_color()
line!(),
column!(),
); );
let df = NuLazyFrame::new(false, df); let df = NuLazyFrame::new(false, df);
@ -441,13 +438,10 @@ fn from_jsonl(
})? })?
.into(); .into();
perf( perf!(
engine,
"Eager json lines dataframe open", "Eager json lines dataframe open",
start_time, start_time,
file!(), engine.use_color()
line!(),
column!(),
); );
df.cache_and_to_value(plugin, engine, call.head) df.cache_and_to_value(plugin, engine, call.head)
@ -524,14 +518,7 @@ fn from_csv(
})? })?
.into(); .into();
perf( perf!("Lazy CSV dataframe open", start_time, engine.use_color());
engine,
"Lazy CSV dataframe open",
start_time,
file!(),
line!(),
column!(),
);
df.cache_and_to_value(plugin, engine, call.head) df.cache_and_to_value(plugin, engine, call.head)
} else { } else {
@ -569,14 +556,7 @@ fn from_csv(
inner: vec![], inner: vec![],
})?; })?;
perf( perf!("Eager CSV dataframe open", start_time, engine.use_color());
engine,
"Eager CSV dataframe open",
start_time,
file!(),
line!(),
column!(),
);
let df = NuDataFrame::new(false, df); let df = NuDataFrame::new(false, df);
df.cache_and_to_value(plugin, engine, call.head) df.cache_and_to_value(plugin, engine, call.head)

View File

@ -45,52 +45,6 @@ impl EngineWrapper for &EngineInterface {
} }
} }
#[macro_export]
macro_rules! plugin_debug {
($env_var_provider:tt, $($arg:tt)*) => {{
if $env_var_provider.get_env_var("POLARS_PLUGIN_DEBUG")
.filter(|s| s == "1" || s == "true")
.is_some() {
eprintln!($($arg)*);
}
}};
}
pub fn perf(
env: impl EngineWrapper,
msg: &str,
dur: std::time::Instant,
file: &str,
line: u32,
column: u32,
) {
if env
.get_env_var("POLARS_PLUGIN_PERF")
.filter(|s| s == "1" || s == "true")
.is_some()
{
if env.use_color() {
eprintln!(
"perf: {}:{}:{} \x1b[32m{}\x1b[0m took \x1b[33m{:?}\x1b[0m",
file,
line,
column,
msg,
dur.elapsed(),
);
} else {
eprintln!(
"perf: {}:{}:{} {} took {:?}",
file,
line,
column,
msg,
dur.elapsed(),
);
}
}
}
#[derive(Default)] #[derive(Default)]
pub struct PolarsPlugin { pub struct PolarsPlugin {
pub(crate) cache: Cache, pub(crate) cache: Cache,

View File

@ -5,5 +5,6 @@ use nu_plugin_polars::PolarsPlugin;
static GLOBAL: mimalloc::MiMalloc = mimalloc::MiMalloc; static GLOBAL: mimalloc::MiMalloc = mimalloc::MiMalloc;
fn main() { fn main() {
env_logger::init();
serve_plugin(&PolarsPlugin::default(), MsgPackSerializer {}) serve_plugin(&PolarsPlugin::default(), MsgPackSerializer {})
} }

View File

@ -29,7 +29,7 @@ use nu_protocol::{
Value, Value,
}; };
use nu_std::load_standard_library; use nu_std::load_standard_library;
use nu_utils::utils::perf; use nu_utils::perf;
use run::{run_commands, run_file, run_repl}; use run::{run_commands, run_file, run_repl};
use signals::ctrlc_protection; use signals::ctrlc_protection;
use std::{ use std::{
@ -219,14 +219,7 @@ fn main() -> Result<()> {
logger(|builder| configure(&level, &target, filters, builder))?; logger(|builder| configure(&level, &target, filters, builder))?;
// info!("start logging {}:{}:{}", file!(), line!(), column!()); // info!("start logging {}:{}:{}", file!(), line!(), column!());
perf( perf!("start logging", start_time, use_color);
"start logging",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
@ -245,27 +238,13 @@ fn main() -> Result<()> {
"env-path", "env-path",
parsed_nu_cli_args.env_file.as_ref(), parsed_nu_cli_args.env_file.as_ref(),
); );
perf( perf!("set_config_path", start_time, use_color);
"set_config_path",
start_time,
file!(),
line!(),
column!(),
use_color,
);
#[cfg(unix)] #[cfg(unix)]
{ {
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
terminal::acquire(engine_state.is_interactive); terminal::acquire(engine_state.is_interactive);
perf( perf!("acquire_terminal", start_time, use_color);
"acquire_terminal",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
@ -279,26 +258,12 @@ fn main() -> Result<()> {
engine_state.add_env_var("NU_LIB_DIRS".into(), Value::list(vals, span)); engine_state.add_env_var("NU_LIB_DIRS".into(), Value::list(vals, span));
} }
perf( perf!("NU_LIB_DIRS setup", start_time, use_color);
"NU_LIB_DIRS setup",
start_time,
file!(),
line!(),
column!(),
use_color,
);
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
// First, set up env vars as strings only // First, set up env vars as strings only
gather_parent_env_vars(&mut engine_state, &init_cwd); gather_parent_env_vars(&mut engine_state, &init_cwd);
perf( perf!("gather env vars", start_time, use_color);
"gather env vars",
start_time,
file!(),
line!(),
column!(),
use_color,
);
engine_state.add_env_var( engine_state.add_env_var(
"NU_VERSION".to_string(), "NU_VERSION".to_string(),
@ -359,14 +324,7 @@ fn main() -> Result<()> {
} }
std::process::exit(0) std::process::exit(0)
} }
perf( perf!("run test_bins", start_time, use_color);
"run test_bins",
start_time,
file!(),
line!(),
column!(),
use_color,
);
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
let input = if let Some(redirect_stdin) = &parsed_nu_cli_args.redirect_stdin { let input = if let Some(redirect_stdin) = &parsed_nu_cli_args.redirect_stdin {
@ -376,26 +334,12 @@ fn main() -> Result<()> {
trace!("not redirecting stdin"); trace!("not redirecting stdin");
PipelineData::empty() PipelineData::empty()
}; };
perf( perf!("redirect stdin", start_time, use_color);
"redirect stdin",
start_time,
file!(),
line!(),
column!(),
use_color,
);
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
// Set up the $nu constant before evaluating config files (need to have $nu available in them) // Set up the $nu constant before evaluating config files (need to have $nu available in them)
engine_state.generate_nu_constant(); engine_state.generate_nu_constant();
perf( perf!("create_nu_constant", start_time, use_color);
"create_nu_constant",
start_time,
file!(),
line!(),
column!(),
use_color,
);
#[cfg(feature = "plugin")] #[cfg(feature = "plugin")]
if let Some(plugins) = &parsed_nu_cli_args.plugins { if let Some(plugins) = &parsed_nu_cli_args.plugins {
@ -433,26 +377,12 @@ fn main() -> Result<()> {
} }
engine_state.merge_delta(working_set.render())?; engine_state.merge_delta(working_set.render())?;
perf( perf!("load plugins specified in --plugins", start_time, use_color)
"load plugins specified in --plugins",
start_time,
file!(),
line!(),
column!(),
use_color,
)
} }
start_time = std::time::Instant::now(); start_time = std::time::Instant::now();
if parsed_nu_cli_args.lsp { if parsed_nu_cli_args.lsp {
perf( perf!("lsp starting", start_time, use_color);
"lsp starting",
start_time,
file!(),
line!(),
column!(),
use_color,
);
if parsed_nu_cli_args.no_config_file.is_none() { if parsed_nu_cli_args.no_config_file.is_none() {
let mut stack = nu_protocol::engine::Stack::new(); let mut stack = nu_protocol::engine::Stack::new();

View File

@ -12,7 +12,7 @@ use nu_protocol::{
engine::{EngineState, Stack}, engine::{EngineState, Stack},
report_error_new, PipelineData, Spanned, report_error_new, PipelineData, Spanned,
}; };
use nu_utils::utils::perf; use nu_utils::perf;
pub(crate) fn run_commands( pub(crate) fn run_commands(
engine_state: &mut EngineState, engine_state: &mut EngineState,
@ -35,14 +35,7 @@ pub(crate) fn run_commands(
#[cfg(feature = "plugin")] #[cfg(feature = "plugin")]
read_plugin_file(engine_state, parsed_nu_cli_args.plugin_file, NUSHELL_FOLDER); read_plugin_file(engine_state, parsed_nu_cli_args.plugin_file, NUSHELL_FOLDER);
perf( perf!("read plugins", start_time, use_color);
"read plugins",
start_time,
file!(),
line!(),
column!(),
use_color,
);
let start_time = std::time::Instant::now(); let start_time = std::time::Instant::now();
// If we have a env file parameter *OR* we have a login shell parameter, read the env file // If we have a env file parameter *OR* we have a login shell parameter, read the env file
@ -57,14 +50,7 @@ pub(crate) fn run_commands(
config_files::read_default_env_file(engine_state, &mut stack) config_files::read_default_env_file(engine_state, &mut stack)
} }
perf( perf!("read env.nu", start_time, use_color);
"read env.nu",
start_time,
file!(),
line!(),
column!(),
use_color,
);
let start_time = std::time::Instant::now(); let start_time = std::time::Instant::now();
// If we have a config file parameter *OR* we have a login shell parameter, read the config file // If we have a config file parameter *OR* we have a login shell parameter, read the config file
@ -77,14 +63,7 @@ pub(crate) fn run_commands(
); );
} }
perf( perf!("read config.nu", start_time, use_color);
"read config.nu",
start_time,
file!(),
line!(),
column!(),
use_color,
);
// If we have a login shell parameter, read the login file // If we have a login shell parameter, read the login file
let start_time = std::time::Instant::now(); let start_time = std::time::Instant::now();
@ -92,14 +71,7 @@ pub(crate) fn run_commands(
config_files::read_loginshell_file(engine_state, &mut stack); config_files::read_loginshell_file(engine_state, &mut stack);
} }
perf( perf!("read login.nu", start_time, use_color);
"read login.nu",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
// Before running commands, set up the startup time // Before running commands, set up the startup time
@ -123,14 +95,7 @@ pub(crate) fn run_commands(
report_error_new(engine_state, &err); report_error_new(engine_state, &err);
std::process::exit(1); std::process::exit(1);
} }
perf( perf!("evaluate_commands", start_time, use_color);
"evaluate_commands",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
pub(crate) fn run_file( pub(crate) fn run_file(
@ -153,14 +118,7 @@ pub(crate) fn run_file(
let start_time = std::time::Instant::now(); let start_time = std::time::Instant::now();
#[cfg(feature = "plugin")] #[cfg(feature = "plugin")]
read_plugin_file(engine_state, parsed_nu_cli_args.plugin_file, NUSHELL_FOLDER); read_plugin_file(engine_state, parsed_nu_cli_args.plugin_file, NUSHELL_FOLDER);
perf( perf!("read plugins", start_time, use_color);
"read plugins",
start_time,
file!(),
line!(),
column!(),
use_color,
);
let start_time = std::time::Instant::now(); let start_time = std::time::Instant::now();
// only want to load config and env if relative argument is provided. // only want to load config and env if relative argument is provided.
@ -174,14 +132,7 @@ pub(crate) fn run_file(
} else { } else {
config_files::read_default_env_file(engine_state, &mut stack) config_files::read_default_env_file(engine_state, &mut stack)
} }
perf( perf!("read env.nu", start_time, use_color);
"read env.nu",
start_time,
file!(),
line!(),
column!(),
use_color,
);
let start_time = std::time::Instant::now(); let start_time = std::time::Instant::now();
if parsed_nu_cli_args.config_file.is_some() { if parsed_nu_cli_args.config_file.is_some() {
@ -192,14 +143,7 @@ pub(crate) fn run_file(
false, false,
); );
} }
perf( perf!("read config.nu", start_time, use_color);
"read config.nu",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
// Regenerate the $nu constant to contain the startup time and any other potential updates // Regenerate the $nu constant to contain the startup time and any other potential updates
@ -216,14 +160,7 @@ pub(crate) fn run_file(
report_error_new(engine_state, &err); report_error_new(engine_state, &err);
std::process::exit(1); std::process::exit(1);
} }
perf( perf!("evaluate_file", start_time, use_color);
"evaluate_file",
start_time,
file!(),
line!(),
column!(),
use_color,
);
let start_time = std::time::Instant::now(); let start_time = std::time::Instant::now();
let last_exit_code = stack.get_env_var(&*engine_state, "LAST_EXIT_CODE"); let last_exit_code = stack.get_env_var(&*engine_state, "LAST_EXIT_CODE");
@ -235,14 +172,7 @@ pub(crate) fn run_file(
} }
} }
} }
perf( perf!("get exit code", start_time, use_color);
"get exit code",
start_time,
file!(),
line!(),
column!(),
use_color,
);
} }
pub(crate) fn run_repl( pub(crate) fn run_repl(
@ -268,14 +198,7 @@ pub(crate) fn run_repl(
// Reload use_color from config in case it's different from the default value // Reload use_color from config in case it's different from the default value
let use_color = engine_state.get_config().use_ansi_coloring; let use_color = engine_state.get_config().use_ansi_coloring;
perf( perf!("setup_config", start_time, use_color);
"setup_config",
start_time,
file!(),
line!(),
column!(),
use_color,
);
let start_time = std::time::Instant::now(); let start_time = std::time::Instant::now();
let ret_val = evaluate_repl( let ret_val = evaluate_repl(
@ -286,14 +209,7 @@ pub(crate) fn run_repl(
parsed_nu_cli_args.no_std_lib, parsed_nu_cli_args.no_std_lib,
entire_start_time, entire_start_time,
); );
perf( perf!("evaluate_repl", start_time, use_color);
"evaluate_repl",
start_time,
file!(),
line!(),
column!(),
use_color,
);
ret_val ret_val
} }