From 84c10de86492038d15a4881973810f0dc4f255a0 Mon Sep 17 00:00:00 2001 From: JT <547158+jntrnr@users.noreply.github.com> Date: Tue, 12 Sep 2023 06:50:03 +1200 Subject: [PATCH] remove profiling from nushell's hot loop (#10325) # Description This removes pipeline element profiling. This could be a useful feature, but pipeline elements are going to be the most sensitive to in terms of performance, as `eval_block` and how pipelines are built is one of the hot loops inside of the eval engine. # User-Facing Changes Removes pipeline element profiling. # Tests + Formatting # After Submitting --- crates/nu-command/src/debug/profile.rs | 15 +-- crates/nu-engine/src/eval.rs | 142 +------------------------ crates/nu-protocol/src/engine/stack.rs | 42 -------- 3 files changed, 6 insertions(+), 193 deletions(-) diff --git a/crates/nu-command/src/debug/profile.rs b/crates/nu-command/src/debug/profile.rs index 3a366d800..6449943fe 100644 --- a/crates/nu-command/src/debug/profile.rs +++ b/crates/nu-command/src/debug/profile.rs @@ -1,6 +1,6 @@ use nu_engine::{eval_block, CallExt}; use nu_protocol::ast::Call; -use nu_protocol::engine::{Closure, Command, EngineState, ProfilingConfig, Stack}; +use nu_protocol::engine::{Closure, Command, EngineState, Stack}; use nu_protocol::{ Category, DataSource, Example, IntoPipelineData, PipelineData, PipelineMetadata, Signature, Spanned, SyntaxShape, Type, Value, @@ -70,24 +70,13 @@ Current known limitations are: } } - stack.profiling_config = ProfilingConfig::new( - call.get_flag::(engine_state, &mut stack, "max-depth")? - .unwrap_or(1), - call.has_flag("source"), - call.has_flag("values"), - ); - - let profiling_metadata = Box::new(PipelineMetadata { - data_source: DataSource::Profiling(vec![]), - }); - let result = if let Some(PipelineMetadata { data_source: DataSource::Profiling(values), }) = eval_block( engine_state, &mut stack, block, - input_val.into_pipeline_data_with_metadata(profiling_metadata), + input_val.into_pipeline_data(), redirect_stdout, redirect_stderr, )? diff --git a/crates/nu-engine/src/eval.rs b/crates/nu-engine/src/eval.rs index 462dbb347..79e3d023c 100644 --- a/crates/nu-engine/src/eval.rs +++ b/crates/nu-engine/src/eval.rs @@ -5,13 +5,11 @@ use nu_protocol::{ eval_operator, Argument, Assignment, Bits, Block, Boolean, Call, Comparison, Expr, Expression, Math, Operator, PathMember, PipelineElement, Redirection, }, - engine::{EngineState, ProfilingConfig, Stack}, - record, DataSource, IntoInterruptiblePipelineData, IntoPipelineData, PipelineData, - PipelineMetadata, Range, Record, ShellError, Span, Spanned, Unit, Value, VarId, - ENV_VARIABLE_ID, + engine::{EngineState, Stack}, + IntoInterruptiblePipelineData, IntoPipelineData, PipelineData, Range, Record, ShellError, Span, + Spanned, Unit, Value, VarId, ENV_VARIABLE_ID, }; use std::collections::HashMap; -use std::time::Instant; pub fn eval_call( engine_state: &EngineState, @@ -1016,13 +1014,6 @@ pub fn eval_block( let num_pipelines = block.len(); - let mut input_metadata = if stack.profiling_config.should_debug() { - stack.profiling_config.enter_block(); - input.metadata() - } else { - None - }; - for (pipeline_idx, pipeline) in block.pipelines.iter().enumerate() { let mut i = 0; @@ -1036,12 +1027,6 @@ pub fn eval_block( | PipelineElement::SeparateRedirection { .. } ))); - let start_time = if stack.profiling_config.should_debug() { - Some(Instant::now()) - } else { - None - }; - // if eval internal command failed, it can just make early return with `Err(ShellError)`. let eval_result = eval_element_with_input( engine_state, @@ -1060,34 +1045,6 @@ pub fn eval_block( redirect_stderr, ); - let end_time = if stack.profiling_config.should_debug() { - Some(Instant::now()) - } else { - None - }; - - if let (Some(start_time), Some(end_time), Some(input_metadata)) = - (start_time, end_time, input_metadata.as_deref_mut()) - { - let element_span = pipeline.elements[i].span(); - let element_str = String::from_utf8_lossy( - engine_state.get_span_contents(pipeline.elements[i].span()), - ) - .to_string(); - - collect_profiling_metadata( - pipeline_idx, - i, - element_str, - element_span, - start_time, - end_time, - &stack.profiling_config, - &eval_result, - input_metadata, - ); - } - match (eval_result, redirect_stderr) { (Ok((pipeline_data, _)), true) => { input = pipeline_data; @@ -1112,9 +1069,6 @@ pub fn eval_block( // make early return so remaining commands will not be executed. // don't return `Err(ShellError)`, so nushell wouldn't show extra error message. if output.1 { - if stack.profiling_config.should_debug() { - stack.profiling_config.leave_block(); - } return Ok(input); } } @@ -1148,12 +1102,7 @@ pub fn eval_block( } } - if stack.profiling_config.should_debug() { - stack.profiling_config.leave_block(); - Ok(input.set_metadata(input_metadata)) - } else { - Ok(input) - } + Ok(input) } pub fn eval_subexpression( @@ -1208,86 +1157,3 @@ pub fn eval_variable( fn compute(size: i64, unit: Unit, span: Span) -> Result { unit.to_value(size, span) } - -#[allow(clippy::too_many_arguments)] -fn collect_profiling_metadata( - pipeline_idx: usize, - element_idx: usize, - element_str: String, - element_span: Span, - start_time: Instant, - end_time: Instant, - profiling_config: &ProfilingConfig, - eval_result: &Result<(PipelineData, bool), ShellError>, - input_metadata: &mut PipelineMetadata, -) { - let element_str = Value::string(element_str, element_span); - let time_ns = (end_time - start_time).as_nanos() as i64; - - let span_record = record! { - "start" => Value::int(element_span.start as i64, element_span), - "end" => Value::int(element_span.end as i64, element_span), - }; - - let mut record = record! { - "pipeline_idx" => Value::int(pipeline_idx as i64, element_span), - "element_idx" => Value::int(element_idx as i64, element_span), - "depth" => Value::int(profiling_config.depth, element_span), - "span" => Value::record(span_record, element_span), - }; - - if profiling_config.collect_source { - record.push("source", element_str); - } - - if profiling_config.collect_values { - let value = match &eval_result { - Ok((PipelineData::Value(val, ..), ..)) => val.clone(), - Ok((PipelineData::ListStream(..), ..)) => Value::string("list-stream", element_span), - Ok((PipelineData::ExternalStream { .. }, ..)) => { - Value::string("raw stream", element_span) - } - Ok((PipelineData::Empty, ..)) => Value::nothing(element_span), - Err(err) => Value::error(err.clone(), element_span), - }; - - record.push("value", value); - } - - record.push("time", Value::duration(time_ns, element_span)); - - let record = Value::record(record, element_span); - - let element_metadata = if let Ok((pipeline_data, ..)) = &eval_result { - pipeline_data.metadata() - } else { - None - }; - - if let PipelineMetadata { - data_source: DataSource::Profiling(tgt_vals), - } = input_metadata - { - tgt_vals.push(record); - } else { - *input_metadata = PipelineMetadata { - data_source: DataSource::Profiling(vec![record]), - }; - } - - if let Some(PipelineMetadata { - data_source: DataSource::Profiling(element_vals), - }) = element_metadata.map(|m| *m) - { - if let PipelineMetadata { - data_source: DataSource::Profiling(tgt_vals), - } = input_metadata - { - tgt_vals.extend(element_vals); - } else { - *input_metadata = PipelineMetadata { - data_source: DataSource::Profiling(element_vals), - }; - } - } -} diff --git a/crates/nu-protocol/src/engine/stack.rs b/crates/nu-protocol/src/engine/stack.rs index 1f9e3628f..4cc3debce 100644 --- a/crates/nu-protocol/src/engine/stack.rs +++ b/crates/nu-protocol/src/engine/stack.rs @@ -7,44 +7,6 @@ use crate::{ShellError, Span, Value, VarId}; /// Environment variables per overlay pub type EnvVars = HashMap>; -#[derive(Debug, Clone)] -pub struct ProfilingConfig { - pub max_depth: i64, - pub depth: i64, - pub collect_source: bool, - pub collect_values: bool, -} - -impl ProfilingConfig { - pub fn new(max_depth: i64, collect_source: bool, collect_values: bool) -> Self { - ProfilingConfig { - max_depth, - depth: 0, - collect_source, - collect_values, - } - } - - pub fn enter_block(&mut self) { - self.depth += 1; - } - - pub fn leave_block(&mut self) { - self.depth -= 1; - } - - pub fn should_debug(&self) -> bool { - self.depth <= self.max_depth - } - - pub fn reset(&mut self) { - self.max_depth = 0; - self.depth = 0; - self.collect_source = false; - self.collect_values = false; - } -} - /// A runtime value stack used during evaluation /// /// A note on implementation: @@ -73,7 +35,6 @@ pub struct Stack { /// List of active overlays pub active_overlays: Vec, pub recursion_count: Box, - pub profiling_config: ProfilingConfig, } impl Stack { @@ -84,7 +45,6 @@ impl Stack { env_hidden: HashMap::new(), active_overlays: vec![DEFAULT_OVERLAY_NAME.to_string()], recursion_count: Box::new(0), - profiling_config: ProfilingConfig::new(0, false, false), } } @@ -195,7 +155,6 @@ impl Stack { env_hidden: self.env_hidden.clone(), active_overlays: self.active_overlays.clone(), recursion_count: self.recursion_count.to_owned(), - profiling_config: self.profiling_config.clone(), } } @@ -223,7 +182,6 @@ impl Stack { env_hidden: self.env_hidden.clone(), active_overlays: self.active_overlays.clone(), recursion_count: self.recursion_count.to_owned(), - profiling_config: self.profiling_config.clone(), } }