Add IR support to the debugger (#13345)

# Description

This adds tracing for each individual instruction to the `Debugger`
trait. Register contents can be inspected both when entering and leaving
an instruction, and if an instruction produced an error, a reference to
the error is also available. It's not the full `EvalContext` but it's
most of the important parts for getting an idea of what's going on.

Added support for all of this to the `Profiler` / `debug profile` as
well, and the output is quite incredible - super verbose, but you can
see every instruction that's executed and also what the result was if
it's an instruction that has a clearly defined output (many do).

# User-Facing Changes

- Added `--instructions` to `debug profile`, which adds the `pc` and
`instruction` columns to the output.
- `--expr` only works in AST mode, and `--instructions` only works in IR
mode. In the wrong mode, the output for those columns is just blank.

# Tests + Formatting

All passing.

# After Submitting

- [ ] release notes

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(
+            ProfilerOptions {
                 max_depth,
                 collect_spans,
-            true,
+                collect_source: true,
                 collect_expanded_source,
                 collect_values,
                 collect_exprs,
+                collect_instructions,
                 collect_lines,
+            },
             call.span(),
         );
 

crates/nu-engine/src/eval_ir.rs

@@ -184,11 +184,20 @@ fn eval_ir_block_impl<D: DebugContext>(
         let instruction = &ir_block.instructions[pc];
         let span = &ir_block.spans[pc];
         let ast = &ir_block.ast[pc];
-        log::trace!(
+
-            "{pc:-4}: {}",
+        D::enter_instruction(ctx.engine_state, ir_block, pc, ctx.registers);
-            instruction.display(ctx.engine_state, ctx.data)
+
+        let result = eval_instruction::<D>(ctx, instruction, span, ast);
+
+        D::leave_instruction(
+            ctx.engine_state,
+            ir_block,
+            pc,
+            ctx.registers,
+            result.as_ref().err(),
         );
-        match eval_instruction::<D>(ctx, instruction, span, ast) {
+
+        match result {
             Ok(InstructionResult::Continue) => {
                 pc += 1;
             }

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<PipelineData, ShellError>,
     ) {
     }
+
+    /// 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()

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<Value>,
     expr: Option<String>,
+    instruction: Option<(usize, String)>,
     children: Vec<ElementId>,
 }
 
@@ -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,
+    opts: ProfilerOptions,
-    collect_spans: bool,
-    collect_source: bool,
-    collect_expanded_source: bool,
-    collect_values: bool,
-    collect_exprs: bool,
-    collect_lines: bool,
     elements: Vec<ElementInfo>,
     element_stack: Vec<ElementId>,
 }
 
 impl Profiler {
     #[allow(clippy::too_many_arguments)]
-    pub fn new(
+    pub fn new(opts: ProfilerOptions, span: Span) -> Self {
-        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 {
         let first = ElementInfo {
             start: Instant::now(),
             duration_sec: 0.0,
             depth: 0,
             element_span: span,
-            element_output: collect_values.then(|| Value::nothing(span)),
+            element_output: opts.collect_values.then(|| Value::nothing(span)),
-            expr: collect_exprs.then(|| "call".to_string()),
+            expr: opts.collect_exprs.then(|| "call".to_string()),
+            instruction: opts
+                .collect_instructions
+                .then(|| (0, "<start>".to_string())),
             children: vec![],
         };
 
         Profiler {
             depth: 0,
-            max_depth,
+            opts,
-            collect_spans,
-            collect_source,
-            collect_expanded_source,
-            collect_values,
-            collect_exprs,
-            collect_lines,
             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<PipelineData, ShellError>,
     ) {
-        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(&registers[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<Value, ShellError> {
         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<PipelineData>, impl Borrow<ShellError>>,
+    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());
     }

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<RegId> {
+        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<usize> {
         match self {