diff --git a/crates/nu-command/src/debug/profile.rs b/crates/nu-command/src/debug/profile.rs index 0cef979094..e8254563df 100644 --- a/crates/nu-command/src/debug/profile.rs +++ b/crates/nu-command/src/debug/profile.rs @@ -1,5 +1,8 @@ use nu_engine::{command_prelude::*, ClosureEvalOnce}; -use nu_protocol::{debugger::Profiler, engine::Closure}; +use nu_protocol::{ + debugger::{Profiler, ProfilerOptions}, + engine::Closure, +}; #[derive(Clone)] pub struct DebugProfile; @@ -28,6 +31,7 @@ impl Command for DebugProfile { Some('v'), ) .switch("expr", "Collect expression types", Some('x')) + .switch("instructions", "Collect IR instructions", Some('i')) .switch("lines", "Collect line numbers", Some('l')) .named( "max-depth", @@ -91,19 +95,23 @@ confusing the id/parent_id hierarchy. The --expr flag is helpful for investigati let collect_expanded_source = call.has_flag(engine_state, stack, "expanded-source")?; let collect_values = call.has_flag(engine_state, stack, "values")?; let collect_exprs = call.has_flag(engine_state, stack, "expr")?; + let collect_instructions = call.has_flag(engine_state, stack, "instructions")?; let collect_lines = call.has_flag(engine_state, stack, "lines")?; let max_depth = call .get_flag(engine_state, stack, "max-depth")? .unwrap_or(2); let profiler = Profiler::new( - max_depth, - collect_spans, - true, - collect_expanded_source, - collect_values, - collect_exprs, - collect_lines, + ProfilerOptions { + max_depth, + collect_spans, + collect_source: true, + collect_expanded_source, + collect_values, + collect_exprs, + collect_instructions, + collect_lines, + }, call.span(), ); diff --git a/crates/nu-engine/src/eval_ir.rs b/crates/nu-engine/src/eval_ir.rs index 56bbccee25..29a677bd69 100644 --- a/crates/nu-engine/src/eval_ir.rs +++ b/crates/nu-engine/src/eval_ir.rs @@ -184,11 +184,20 @@ fn eval_ir_block_impl( let instruction = &ir_block.instructions[pc]; let span = &ir_block.spans[pc]; let ast = &ir_block.ast[pc]; - log::trace!( - "{pc:-4}: {}", - instruction.display(ctx.engine_state, ctx.data) + + D::enter_instruction(ctx.engine_state, ir_block, pc, ctx.registers); + + let result = eval_instruction::(ctx, instruction, span, ast); + + D::leave_instruction( + ctx.engine_state, + ir_block, + pc, + ctx.registers, + result.as_ref().err(), ); - match eval_instruction::(ctx, instruction, span, ast) { + + match result { Ok(InstructionResult::Continue) => { pc += 1; } diff --git a/crates/nu-protocol/src/debugger/debugger_trait.rs b/crates/nu-protocol/src/debugger/debugger_trait.rs index 69d395fb98..88cc753548 100644 --- a/crates/nu-protocol/src/debugger/debugger_trait.rs +++ b/crates/nu-protocol/src/debugger/debugger_trait.rs @@ -16,6 +16,7 @@ use crate::{ ast::{Block, PipelineElement}, engine::EngineState, + ir::IrBlock, PipelineData, ShellError, Span, Value, }; use std::{fmt::Debug, ops::DerefMut}; @@ -35,11 +36,11 @@ pub trait DebugContext: Clone + Copy + Debug { #[allow(unused_variables)] fn leave_block(engine_state: &EngineState, block: &Block) {} - /// Called when the evaluator enters a pipeline element + /// Called when the AST evaluator enters a pipeline element #[allow(unused_variables)] fn enter_element(engine_state: &EngineState, element: &PipelineElement) {} - /// Called when the evaluator leaves a pipeline element + /// Called when the AST evaluator leaves a pipeline element #[allow(unused_variables)] fn leave_element( engine_state: &EngineState, @@ -47,6 +48,27 @@ pub trait DebugContext: Clone + Copy + Debug { result: &Result, ) { } + + /// Called before the IR evaluator runs an instruction + #[allow(unused_variables)] + fn enter_instruction( + engine_state: &EngineState, + ir_block: &IrBlock, + instruction_index: usize, + registers: &[PipelineData], + ) { + } + + /// Called after the IR evaluator runs an instruction + #[allow(unused_variables)] + fn leave_instruction( + engine_state: &EngineState, + ir_block: &IrBlock, + instruction_index: usize, + registers: &[PipelineData], + error: Option<&ShellError>, + ) { + } } /// Marker struct signalizing that evaluation should use a Debugger @@ -85,6 +107,40 @@ impl DebugContext for WithDebug { .leave_element(engine_state, element, result); } } + + fn enter_instruction( + engine_state: &EngineState, + ir_block: &IrBlock, + instruction_index: usize, + registers: &[PipelineData], + ) { + if let Ok(mut debugger) = engine_state.debugger.lock() { + debugger.deref_mut().enter_instruction( + engine_state, + ir_block, + instruction_index, + registers, + ) + } + } + + fn leave_instruction( + engine_state: &EngineState, + ir_block: &IrBlock, + instruction_index: usize, + registers: &[PipelineData], + error: Option<&ShellError>, + ) { + if let Ok(mut debugger) = engine_state.debugger.lock() { + debugger.deref_mut().leave_instruction( + engine_state, + ir_block, + instruction_index, + registers, + error, + ) + } + } } /// Marker struct signalizing that evaluation should NOT use a Debugger @@ -118,11 +174,11 @@ pub trait Debugger: Send + Debug { #[allow(unused_variables)] fn leave_block(&mut self, engine_state: &EngineState, block: &Block) {} - /// Called when the evaluator enters a pipeline element + /// Called when the AST evaluator enters a pipeline element #[allow(unused_variables)] fn enter_element(&mut self, engine_state: &EngineState, pipeline_element: &PipelineElement) {} - /// Called when the evaluator leaves a pipeline element + /// Called when the AST evaluator leaves a pipeline element #[allow(unused_variables)] fn leave_element( &mut self, @@ -132,6 +188,29 @@ pub trait Debugger: Send + Debug { ) { } + /// Called before the IR evaluator runs an instruction + #[allow(unused_variables)] + fn enter_instruction( + &mut self, + engine_state: &EngineState, + ir_block: &IrBlock, + instruction_index: usize, + registers: &[PipelineData], + ) { + } + + /// Called after the IR evaluator runs an instruction + #[allow(unused_variables)] + fn leave_instruction( + &mut self, + engine_state: &EngineState, + ir_block: &IrBlock, + instruction_index: usize, + registers: &[PipelineData], + error: Option<&ShellError>, + ) { + } + /// Create a final report as a Value /// /// Intended to be called after deactivate() diff --git a/crates/nu-protocol/src/debugger/profiler.rs b/crates/nu-protocol/src/debugger/profiler.rs index c3066c0a14..c61ee04d12 100644 --- a/crates/nu-protocol/src/debugger/profiler.rs +++ b/crates/nu-protocol/src/debugger/profiler.rs @@ -7,10 +7,11 @@ use crate::{ ast::{Block, Expr, PipelineElement}, debugger::Debugger, engine::EngineState, + ir::IrBlock, record, PipelineData, ShellError, Span, Value, }; -use std::io::BufRead; use std::time::Instant; +use std::{borrow::Borrow, io::BufRead}; #[derive(Debug, Clone, Copy)] struct ElementId(usize); @@ -24,6 +25,7 @@ struct ElementInfo { element_span: Span, element_output: Option, expr: Option, + instruction: Option<(usize, String)>, children: Vec, } @@ -36,57 +38,53 @@ impl ElementInfo { element_span, element_output: None, expr: None, + instruction: None, children: vec![], } } } +/// Options for [`Profiler`] +#[derive(Debug, Clone)] +pub struct ProfilerOptions { + pub max_depth: i64, + pub collect_spans: bool, + pub collect_source: bool, + pub collect_expanded_source: bool, + pub collect_values: bool, + pub collect_exprs: bool, + pub collect_instructions: bool, + pub collect_lines: bool, +} + /// Basic profiler, used in `debug profile` #[derive(Debug, Clone)] pub struct Profiler { depth: i64, - max_depth: i64, - collect_spans: bool, - collect_source: bool, - collect_expanded_source: bool, - collect_values: bool, - collect_exprs: bool, - collect_lines: bool, + opts: ProfilerOptions, elements: Vec, element_stack: Vec, } impl Profiler { #[allow(clippy::too_many_arguments)] - pub fn new( - max_depth: i64, - collect_spans: bool, - collect_source: bool, - collect_expanded_source: bool, - collect_values: bool, - collect_exprs: bool, - collect_lines: bool, - span: Span, - ) -> Self { + pub fn new(opts: ProfilerOptions, span: Span) -> Self { let first = ElementInfo { start: Instant::now(), duration_sec: 0.0, depth: 0, element_span: span, - element_output: collect_values.then(|| Value::nothing(span)), - expr: collect_exprs.then(|| "call".to_string()), + element_output: opts.collect_values.then(|| Value::nothing(span)), + expr: opts.collect_exprs.then(|| "call".to_string()), + instruction: opts + .collect_instructions + .then(|| (0, "".to_string())), children: vec![], }; Profiler { depth: 0, - max_depth, - collect_spans, - collect_source, - collect_expanded_source, - collect_values, - collect_exprs, - collect_lines, + opts, elements: vec![first], element_stack: vec![ElementId(0)], } @@ -130,7 +128,7 @@ impl Debugger for Profiler { } fn enter_element(&mut self, engine_state: &EngineState, element: &PipelineElement) { - if self.depth > self.max_depth { + if self.depth > self.opts.max_depth { return; } @@ -140,6 +138,7 @@ impl Debugger for Profiler { }; let expr_opt = self + .opts .collect_exprs .then(|| expr_to_string(engine_state, &element.expr.expr)); @@ -165,13 +164,13 @@ impl Debugger for Profiler { element: &PipelineElement, result: &Result, ) { - if self.depth > self.max_depth { + if self.depth > self.opts.max_depth { return; } let element_span = element.expr.span; - let out_opt = self.collect_values.then(|| match result { + let out_opt = self.opts.collect_values.then(|| match result { Ok(pipeline_data) => match pipeline_data { PipelineData::Value(val, ..) => val.clone(), PipelineData::ListStream(..) => Value::string("list stream", element_span), @@ -192,6 +191,91 @@ impl Debugger for Profiler { self.element_stack.pop(); } + fn enter_instruction( + &mut self, + engine_state: &EngineState, + ir_block: &IrBlock, + instruction_index: usize, + _registers: &[PipelineData], + ) { + if self.depth > self.opts.max_depth { + return; + } + + let Some(parent_id) = self.last_element_id() else { + eprintln!("Profiler Error: Missing parent element ID."); + return; + }; + + let instruction = &ir_block.instructions[instruction_index]; + let span = ir_block.spans[instruction_index]; + + let instruction_opt = self.opts.collect_instructions.then(|| { + ( + instruction_index, + instruction + .display(engine_state, &ir_block.data) + .to_string(), + ) + }); + + let new_id = ElementId(self.elements.len()); + + let mut new_element = ElementInfo::new(self.depth, span); + new_element.instruction = instruction_opt; + + self.elements.push(new_element); + + let Some(parent) = self.elements.get_mut(parent_id.0) else { + eprintln!("Profiler Error: Missing parent element."); + return; + }; + + parent.children.push(new_id); + self.element_stack.push(new_id); + } + + fn leave_instruction( + &mut self, + _engine_state: &EngineState, + ir_block: &IrBlock, + instruction_index: usize, + registers: &[PipelineData], + error: Option<&ShellError>, + ) { + if self.depth > self.opts.max_depth { + return; + } + + let instruction = &ir_block.instructions[instruction_index]; + let span = ir_block.spans[instruction_index]; + + let out_opt = self + .opts + .collect_values + .then(|| { + error + .map(Err) + .or_else(|| { + instruction + .output_register() + .map(|register| Ok(®isters[register.0 as usize])) + }) + .map(|result| format_result(&result, span)) + }) + .flatten(); + + let Some(last_element) = self.last_element_mut() else { + eprintln!("Profiler Error: Missing last element."); + return; + }; + + last_element.duration_sec = last_element.start.elapsed().as_secs_f64(); + last_element.element_output = out_opt; + + self.element_stack.pop(); + } + fn report(&self, engine_state: &EngineState, profiler_span: Span) -> Result { Ok(Value::list( collect_data( @@ -268,6 +352,21 @@ fn expr_to_string(engine_state: &EngineState, expr: &Expr) -> String { } } +fn format_result( + result: &Result, impl Borrow>, + element_span: Span, +) -> Value { + match result { + Ok(pipeline_data) => match pipeline_data.borrow() { + PipelineData::Value(val, ..) => val.clone(), + PipelineData::ListStream(..) => Value::string("list stream", element_span), + PipelineData::ByteStream(..) => Value::string("byte stream", element_span), + _ => Value::nothing(element_span), + }, + Err(e) => Value::error(e.borrow().clone(), element_span), + } +} + // Find a file name and a line number (indexed from 1) of a span fn find_file_of_span(engine_state: &EngineState, span: Span) -> Option<(&str, usize)> { for file in engine_state.files() { @@ -308,7 +407,7 @@ fn collect_data( "parent_id" => Value::int(parent_id.0 as i64, profiler_span), }; - if profiler.collect_lines { + if profiler.opts.collect_lines { if let Some((fname, line_num)) = find_file_of_span(engine_state, element.element_span) { row.push("file", Value::string(fname, profiler_span)); row.push("line", Value::int(line_num as i64, profiler_span)); @@ -318,7 +417,7 @@ fn collect_data( } } - if profiler.collect_spans { + if profiler.opts.collect_spans { let span_start = i64::try_from(element.element_span.start) .map_err(|_| profiler_error("error converting span start to i64", profiler_span))?; let span_end = i64::try_from(element.element_span.end) @@ -336,12 +435,12 @@ fn collect_data( ); } - if profiler.collect_source { + if profiler.opts.collect_source { let val = String::from_utf8_lossy(engine_state.get_span_contents(element.element_span)); let val = val.trim(); let nlines = val.lines().count(); - let fragment = if profiler.collect_expanded_source { + let fragment = if profiler.opts.collect_expanded_source { val.to_string() } else { let mut first_line = val.lines().next().unwrap_or("").to_string(); @@ -360,6 +459,17 @@ fn collect_data( row.push("expr", Value::string(expr_string.clone(), profiler_span)); } + if let Some((instruction_index, instruction)) = &element.instruction { + row.push( + "pc", + (*instruction_index) + .try_into() + .map(|index| Value::int(index, profiler_span)) + .unwrap_or(Value::nothing(profiler_span)), + ); + row.push("instruction", Value::string(instruction, profiler_span)); + } + if let Some(val) = &element.element_output { row.push("output", val.clone()); } diff --git a/crates/nu-protocol/src/ir/mod.rs b/crates/nu-protocol/src/ir/mod.rs index a1b2439768..aff5f42c8c 100644 --- a/crates/nu-protocol/src/ir/mod.rs +++ b/crates/nu-protocol/src/ir/mod.rs @@ -276,6 +276,63 @@ impl Instruction { } } + /// Get the output register, for instructions that produce some kind of immediate result. + pub fn output_register(&self) -> Option { + match *self { + Instruction::Unreachable => None, + Instruction::LoadLiteral { dst, .. } => Some(dst), + Instruction::LoadValue { dst, .. } => Some(dst), + Instruction::Move { dst, .. } => Some(dst), + Instruction::Clone { dst, .. } => Some(dst), + Instruction::Collect { src_dst } => Some(src_dst), + Instruction::Span { src_dst } => Some(src_dst), + Instruction::Drop { .. } => None, + Instruction::Drain { .. } => None, + Instruction::LoadVariable { dst, .. } => Some(dst), + Instruction::StoreVariable { .. } => None, + Instruction::LoadEnv { dst, .. } => Some(dst), + Instruction::LoadEnvOpt { dst, .. } => Some(dst), + Instruction::StoreEnv { .. } => None, + Instruction::PushPositional { .. } => None, + Instruction::AppendRest { .. } => None, + Instruction::PushFlag { .. } => None, + Instruction::PushShortFlag { .. } => None, + Instruction::PushNamed { .. } => None, + Instruction::PushShortNamed { .. } => None, + Instruction::PushParserInfo { .. } => None, + Instruction::RedirectOut { .. } => None, + Instruction::RedirectErr { .. } => None, + Instruction::CheckErrRedirected { .. } => None, + Instruction::OpenFile { .. } => None, + Instruction::WriteFile { .. } => None, + Instruction::CloseFile { .. } => None, + Instruction::Call { src_dst, .. } => Some(src_dst), + Instruction::StringAppend { src_dst, .. } => Some(src_dst), + Instruction::GlobFrom { src_dst, .. } => Some(src_dst), + Instruction::ListPush { src_dst, .. } => Some(src_dst), + Instruction::ListSpread { src_dst, .. } => Some(src_dst), + Instruction::RecordInsert { src_dst, .. } => Some(src_dst), + Instruction::RecordSpread { src_dst, .. } => Some(src_dst), + Instruction::Not { src_dst } => Some(src_dst), + Instruction::BinaryOp { lhs_dst, .. } => Some(lhs_dst), + Instruction::FollowCellPath { src_dst, .. } => Some(src_dst), + Instruction::CloneCellPath { dst, .. } => Some(dst), + Instruction::UpsertCellPath { src_dst, .. } => Some(src_dst), + Instruction::Jump { .. } => None, + Instruction::BranchIf { .. } => None, + Instruction::BranchIfEmpty { .. } => None, + Instruction::Match { .. } => None, + Instruction::CheckMatchGuard { .. } => None, + Instruction::Iterate { dst, .. } => Some(dst), + Instruction::OnError { .. } => None, + Instruction::OnErrorInto { .. } => None, + Instruction::PopErrorHandler => None, + Instruction::CheckExternalFailed { dst, .. } => Some(dst), + Instruction::ReturnEarly { .. } => None, + Instruction::Return { .. } => None, + } + } + /// Returns the branch target index of the instruction if this is a branching instruction. pub fn branch_target(&self) -> Option { match self {