Debugger experiments (#11441)

# Description  This PR adds a new evaluator path with callbacks to a mutable trait object implementing a Debugger trait. The trait object can do anything, e.g., profiling, code coverage, step debugging. Currently, entering/leaving a block and a pipeline element is marked with callbacks, but more callbacks can be added as necessary. Not all callbacks need to be used by all debuggers; unused ones are simply empty calls. A simple profiler is implemented as a proof of concept. The debugging support is implementing by making `eval_xxx()` functions generic depending on whether we're debugging or not. This has zero computational overhead, but makes the binary slightly larger (see benchmarks below). `eval_xxx()` variants called from commands (like `eval_block_with_early_return()` in `each`) are chosen with a dynamic dispatch for two reasons: to not grow the binary size due to duplicating the code of many commands, and for the fact that it isn't possible because it would make Command trait objects object-unsafe. In the future, I hope it will be possible to allow plugin callbacks such that users would be able to implement their profiler plugins instead of having to recompile Nushell. [DAP](https://microsoft.github.io/debug-adapter-protocol/) would also be interesting to explore. Try `help debug profile`. ## Screenshots Basic output: ![profiler_new](https://github.com/nushell/nushell/assets/25571562/418b9df0-b659-4dcb-b023-2d5fcef2c865) To profile with more granularity, increase the profiler depth (you'll see that repeated `is-windows` calls take a large chunk of total time, making it a good candidate for optimizing): ![profiler_new_m3](https://github.com/nushell/nushell/assets/25571562/636d756d-5d56-460c-a372-14716f65f37f) ## Benchmarks ### Binary size Binary size increase vs. main: **+40360 bytes**. _(Both built with `--release --features=extra,dataframe`.)_ ### Time ```nushell # bench_debug.nu use std bench let test = { 1..100 | each { ls | each {|row| $row.name | str length } } | flatten | math avg } print 'debug:' let res2 = bench { debug profile $test } --pretty print $res2 ``` ```nushell # bench_nodebug.nu use std bench let test = { 1..100 | each { ls | each {|row| $row.name | str length } } | flatten | math avg } print 'no debug:' let res1 = bench { do $test } --pretty print $res1 ``` `cargo run --release -- bench_debug.nu` is consistently 1--2 ms slower than `cargo run --release -- bench_nodebug.nu` due to the collection overhead + gathering the report. This is expected. When gathering more stuff, the overhead is obviously higher. `cargo run --release -- bench_nodebug.nu` vs. `nu bench_nodebug.nu` I didn't measure any difference. Both benchmarks report times between 97 and 103 ms randomly, without one being consistently higher than the other. This suggests that at least in this particular case, when not running any debugger, there is no runtime overhead. ## API changes This PR adds a generic parameter to all `eval_xxx` functions that forces you to specify whether you use the debugger. You can resolve it in two ways: * Use a provided helper that will figure it out for you. If you wanted to use `eval_block(&engine_state, ...)`, call `let eval_block = get_eval_block(&engine_state); eval_block(&engine_state, ...)` * If you know you're in an evaluation path that doesn't need debugger support, call `eval_block::<WithoutDebug>(&engine_state, ...)` (this is the case of hooks, for example). I tried to add more explanation in the docstring of `debugger_trait.rs`. ## TODO - [x] Better profiler output to reduce spam of iterative commands like `each` - [x] Resolve `TODO: DEBUG` comments - [x] Resolve unwraps - [x] Add doc comments - [x] Add usage and extra usage for `debug profile`, explaining all columns # User-Facing Changes  Hopefully none. # Tests + Formatting  # After Submitting
2024-03-08 20:21:35 +02:00
parent a9ddc58f21
commit 14d1c67863
81 changed files with 1297 additions and 205 deletions
--- a/crates/nu-protocol/src/debugger/debugger_trait.rs
+++ b/crates/nu-protocol/src/debugger/debugger_trait.rs
@@ -0,0 +1,149 @@
+//! Traits related to debugging
+//!
+//! The purpose of DebugContext is achieving static dispatch on `eval_xxx()` calls.
+//! The main Debugger trait is intended to be used as a trait object.
+//!
+//! The debugging information is stored in `EngineState` as the `debugger` field storing a `Debugger`
+//! trait object behind `Arc` and `Mutex`. To evaluate something (e.g., a block), first create a
+//! `Debugger` trait object (such as the `Profiler`). Then, add it to engine state via
+//! `engine_state.activate_debugger()`. This sets the internal state of EngineState to the debugging
+//! mode and calls `Debugger::activate()`. Now, you can call `eval_xxx::<WithDebug>()`. When you're
+//! done, call `engine_state.deactivate_debugger()` which calls `Debugger::deactivate()`, sets the
+//! EngineState into non-debugging mode, and returns the original mutated `Debugger` trait object.
+//! (`NoopDebugger` is placed in its place inside `EngineState`.) After deactivating, you can call
+//! `Debugger::report()` to get some output from the debugger, if necessary.
+
+use crate::ast::{Block, PipelineElement};
+use crate::engine::EngineState;
+use crate::{PipelineData, ShellError, Span, Value};
+use std::fmt::Debug;
+use std::ops::DerefMut;
+
+/// Trait used for static dispatch of `eval_xxx()` evaluator calls
+///
+/// DebugContext implements the same interface as Debugger (except activate() and deactivate(). It
+/// is intended to be implemented only by two structs
+/// * WithDebug which calls down to the Debugger methods
+/// * WithoutDebug with default implementation, i.e., empty calls to be optimized away
+pub trait DebugContext: Clone + Copy + Debug {
+    /// Called when the evaluator enters a block
+    #[allow(unused_variables)]
+    fn enter_block(engine_state: &EngineState, block: &Block) {}
+
+    /// Called when the evaluator leaves a block
+    #[allow(unused_variables)]
+    fn leave_block(engine_state: &EngineState, block: &Block) {}
+
+    /// Called when the evaluator enters a pipeline element
+    #[allow(unused_variables)]
+    fn enter_element(engine_state: &EngineState, element: &PipelineElement) {}
+
+    /// Called when the evaluator leaves a pipeline element
+    #[allow(unused_variables)]
+    fn leave_element(
+        engine_state: &EngineState,
+        element: &PipelineElement,
+        result: &Result<(PipelineData, bool), ShellError>,
+    ) {
+    }
+}
+
+/// Marker struct signalizing that evaluation should use a Debugger
+///
+/// Trait methods call to Debugger trait object inside the supplied EngineState.
+#[derive(Clone, Copy, Debug)]
+pub struct WithDebug;
+
+impl DebugContext for WithDebug {
+    fn enter_block(engine_state: &EngineState, block: &Block) {
+        if let Ok(mut debugger) = engine_state.debugger.lock() {
+            debugger.deref_mut().enter_block(engine_state, block);
+        }
+    }
+
+    fn leave_block(engine_state: &EngineState, block: &Block) {
+        if let Ok(mut debugger) = engine_state.debugger.lock() {
+            debugger.deref_mut().leave_block(engine_state, block);
+        }
+    }
+
+    fn enter_element(engine_state: &EngineState, element: &PipelineElement) {
+        if let Ok(mut debugger) = engine_state.debugger.lock() {
+            debugger.deref_mut().enter_element(engine_state, element);
+        }
+    }
+
+    fn leave_element(
+        engine_state: &EngineState,
+        element: &PipelineElement,
+        result: &Result<(PipelineData, bool), ShellError>,
+    ) {
+        if let Ok(mut debugger) = engine_state.debugger.lock() {
+            debugger
+                .deref_mut()
+                .leave_element(engine_state, element, result);
+        }
+    }
+}
+
+/// Marker struct signalizing that evaluation should NOT use a Debugger
+///
+/// Trait methods are empty calls to be optimized away.
+#[derive(Clone, Copy, Debug)]
+pub struct WithoutDebug;
+
+impl DebugContext for WithoutDebug {}
+
+/// Debugger trait that every debugger needs to implement.
+///
+/// By default, its methods are empty. Not every Debugger needs to implement all of them.
+pub trait Debugger: Send + Debug {
+    /// Called by EngineState::activate_debugger().
+    ///
+    /// Intended for initializing the debugger.
+    fn activate(&mut self) {}
+
+    /// Called by EngineState::deactivate_debugger().
+    ///
+    /// Intended for wrapping up the debugger after a debugging session before returning back to
+    /// normal evaluation without debugging.
+    fn deactivate(&mut self) {}
+
+    /// Called when the evaluator enters a block
+    #[allow(unused_variables)]
+    fn enter_block(&mut self, engine_state: &EngineState, block: &Block) {}
+
+    /// Called when the evaluator leaves a block
+    #[allow(unused_variables)]
+    fn leave_block(&mut self, engine_state: &EngineState, block: &Block) {}
+
+    /// Called when the 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
+    #[allow(unused_variables)]
+    fn leave_element(
+        &mut self,
+        engine_state: &EngineState,
+        element: &PipelineElement,
+        result: &Result<(PipelineData, bool), ShellError>,
+    ) {
+    }
+
+    /// Create a final report as a Value
+    ///
+    /// Intended to be called after deactivate()
+    #[allow(unused_variables)]
+    fn report(&self, engine_state: &EngineState, debugger_span: Span) -> Result<Value, ShellError> {
+        Ok(Value::nothing(debugger_span))
+    }
+}
+
+/// A debugger that does nothing
+///
+/// Used as a placeholder debugger when not debugging.
+#[derive(Debug)]
+pub struct NoopDebugger;
+
+impl Debugger for NoopDebugger {}
--- a/crates/nu-protocol/src/debugger/mod.rs
+++ b/crates/nu-protocol/src/debugger/mod.rs
@@ -0,0 +1,5 @@
+pub mod debugger_trait;
+pub mod profiler;
+
+pub use debugger_trait::*;
+pub use profiler::*;
--- a/crates/nu-protocol/src/debugger/profiler.rs
+++ b/crates/nu-protocol/src/debugger/profiler.rs
@@ -0,0 +1,360 @@
+//! Nushell Profiler
+//!
+//! Profiler implements the Debugger trait and can be used via the `debug profile` command for
+//! profiling Nushell code.
+
+use crate::ast::{Block, Expr, PipelineElement};
+use crate::debugger::Debugger;
+use crate::engine::EngineState;
+use crate::record;
+use crate::{PipelineData, ShellError, Span, Value};
+use std::time::Instant;
+
+#[derive(Debug, Clone, Copy)]
+struct ElementId(usize);
+
+/// Stores profiling information about one pipeline element
+#[derive(Debug, Clone)]
+struct ElementInfo {
+    start: Instant,
+    duration_sec: f64,
+    depth: i64,
+    element_span: Span,
+    element_output: Option<Value>,
+    expr: Option<String>,
+    children: Vec<ElementId>,
+}
+
+impl ElementInfo {
+    pub fn new(depth: i64, element_span: Span) -> Self {
+        ElementInfo {
+            start: Instant::now(),
+            duration_sec: 0.0,
+            depth,
+            element_span,
+            element_output: None,
+            expr: None,
+            children: vec![],
+        }
+    }
+}
+
+/// 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,
+    elements: Vec<ElementInfo>,
+    element_stack: Vec<ElementId>,
+}
+
+impl Profiler {
+    pub fn new(
+        max_depth: i64,
+        collect_spans: bool,
+        collect_source: bool,
+        collect_expanded_source: bool,
+        collect_values: bool,
+        collect_exprs: bool,
+        span: Span,
+    ) -> Self {
+        let first = ElementInfo {
+            start: Instant::now(),
+            duration_sec: 0.0,
+            depth: 0,
+            element_span: span,
+            element_output: if collect_values {
+                Some(Value::nothing(span))
+            } else {
+                None
+            },
+            expr: if collect_exprs {
+                Some("call".to_string())
+            } else {
+                None
+            },
+            children: vec![],
+        };
+
+        Profiler {
+            depth: 0,
+            max_depth,
+            collect_spans,
+            collect_source,
+            collect_expanded_source,
+            collect_values,
+            collect_exprs,
+            elements: vec![first],
+            element_stack: vec![ElementId(0)],
+        }
+    }
+
+    fn last_element_id(&self) -> Option<ElementId> {
+        self.element_stack.last().copied()
+    }
+
+    fn last_element_mut(&mut self) -> Option<&mut ElementInfo> {
+        self.last_element_id()
+            .and_then(|id| self.elements.get_mut(id.0))
+    }
+}
+
+impl Debugger for Profiler {
+    fn activate(&mut self) {
+        let Some(root_element) = self.last_element_mut() else {
+            eprintln!("Profiler Error: Missing root element.");
+            return;
+        };
+
+        root_element.start = Instant::now();
+    }
+
+    fn deactivate(&mut self) {
+        let Some(root_element) = self.last_element_mut() else {
+            eprintln!("Profiler Error: Missing root element.");
+            return;
+        };
+
+        root_element.duration_sec = root_element.start.elapsed().as_secs_f64();
+    }
+
+    fn enter_block(&mut self, _engine_state: &EngineState, _block: &Block) {
+        self.depth += 1;
+    }
+
+    fn leave_block(&mut self, _engine_state: &EngineState, _block: &Block) {
+        self.depth -= 1;
+    }
+
+    fn enter_element(&mut self, engine_state: &EngineState, element: &PipelineElement) {
+        if self.depth > self.max_depth {
+            return;
+        }
+
+        let Some(parent_id) = self.last_element_id() else {
+            eprintln!("Profiler Error: Missing parent element ID.");
+            return;
+        };
+
+        let expr_opt = if self.collect_exprs {
+            Some(match element {
+                PipelineElement::Expression(_, expression) => {
+                    expr_to_string(engine_state, &expression.expr)
+                }
+                _ => "other".to_string(),
+            })
+        } else {
+            None
+        };
+
+        let new_id = ElementId(self.elements.len());
+
+        let mut new_element = ElementInfo::new(self.depth, element.span());
+        new_element.expr = expr_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_element(
+        &mut self,
+        _engine_state: &EngineState,
+        element: &PipelineElement,
+        result: &Result<(PipelineData, bool), ShellError>,
+    ) {
+        if self.depth > self.max_depth {
+            return;
+        }
+
+        let element_span = element.span();
+
+        let out_opt = if self.collect_values {
+            Some(match result {
+                Ok((pipeline_data, _not_sure_what_this_is)) => match pipeline_data {
+                    PipelineData::Value(val, ..) => val.clone(),
+                    PipelineData::ListStream(..) => Value::string("list stream", element_span),
+                    PipelineData::ExternalStream { .. } => {
+                        Value::string("external stream", element_span)
+                    }
+                    _ => Value::nothing(element_span),
+                },
+                Err(e) => Value::error(e.clone(), element_span),
+            })
+        } else {
+            None
+        };
+
+        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(
+                engine_state,
+                self,
+                ElementId(0),
+                ElementId(0),
+                profiler_span,
+            )?,
+            profiler_span,
+        ))
+    }
+}
+
+fn profiler_error(msg: impl Into<String>, span: Span) -> ShellError {
+    ShellError::GenericError {
+        error: "Profiler Error".to_string(),
+        msg: msg.into(),
+        span: Some(span),
+        help: None,
+        inner: vec![],
+    }
+}
+
+fn expr_to_string(engine_state: &EngineState, expr: &Expr) -> String {
+    match expr {
+        Expr::Binary(_) => "binary".to_string(),
+        Expr::BinaryOp(_, _, _) => "binary operation".to_string(),
+        Expr::Block(_) => "block".to_string(),
+        Expr::Bool(_) => "bool".to_string(),
+        Expr::Call(call) => {
+            let decl = engine_state.get_decl(call.decl_id);
+            if decl.name() == "collect" && call.head == Span::new(0, 0) {
+                "call (implicit collect)"
+            } else {
+                "call"
+            }
+            .to_string()
+        }
+        Expr::CellPath(_) => "cell path".to_string(),
+        Expr::Closure(_) => "closure".to_string(),
+        Expr::DateTime(_) => "datetime".to_string(),
+        Expr::Directory(_, _) => "directory".to_string(),
+        Expr::ExternalCall(_, _, _) => "external call".to_string(),
+        Expr::Filepath(_, _) => "filepath".to_string(),
+        Expr::Float(_) => "float".to_string(),
+        Expr::FullCellPath(full_cell_path) => {
+            let head = expr_to_string(engine_state, &full_cell_path.head.expr);
+            format!("full cell path ({head})")
+        }
+        Expr::Garbage => "garbage".to_string(),
+        Expr::GlobPattern(_, _) => "glob pattern".to_string(),
+        Expr::ImportPattern(_) => "import pattern".to_string(),
+        Expr::Int(_) => "int".to_string(),
+        Expr::Keyword(_, _, _) => "keyword".to_string(),
+        Expr::List(_) => "list".to_string(),
+        Expr::MatchBlock(_) => "match block".to_string(),
+        Expr::Nothing => "nothing".to_string(),
+        Expr::Operator(_) => "operator".to_string(),
+        Expr::Overlay(_) => "overlay".to_string(),
+        Expr::Range(_, _, _, _) => "range".to_string(),
+        Expr::Record(_) => "record".to_string(),
+        Expr::RowCondition(_) => "row condition".to_string(),
+        Expr::Signature(_) => "signature".to_string(),
+        Expr::Spread(_) => "spread".to_string(),
+        Expr::String(_) => "string".to_string(),
+        Expr::StringInterpolation(_) => "string interpolation".to_string(),
+        Expr::Subexpression(_) => "subexpression".to_string(),
+        Expr::Table(_, _) => "table".to_string(),
+        Expr::UnaryNot(_) => "unary not".to_string(),
+        Expr::ValueWithUnit(_, _) => "value with unit".to_string(),
+        Expr::Var(_) => "var".to_string(),
+        Expr::VarDecl(_) => "var decl".to_string(),
+    }
+}
+
+fn collect_data(
+    engine_state: &EngineState,
+    profiler: &Profiler,
+    element_id: ElementId,
+    parent_id: ElementId,
+    profiler_span: Span,
+) -> Result<Vec<Value>, ShellError> {
+    let element = &profiler.elements[element_id.0];
+
+    let mut row = record! {
+        "depth" => Value::int(element.depth, profiler_span),
+        "id" => Value::int(element_id.0 as i64, profiler_span),
+        "parent_id" => Value::int(parent_id.0 as i64, profiler_span),
+    };
+
+    if profiler.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)
+            .map_err(|_| profiler_error("error converting span end to i64", profiler_span))?;
+
+        row.push(
+            "span",
+            Value::record(
+                record! {
+                    "start" => Value::int(span_start, profiler_span),
+                    "end" => Value::int(span_end, profiler_span),
+                },
+                profiler_span,
+            ),
+        );
+    }
+
+    if profiler.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 {
+            val.to_string()
+        } else {
+            let mut first_line = val.lines().next().unwrap_or("").to_string();
+
+            if nlines > 1 {
+                first_line.push_str(" ...");
+            }
+
+            first_line
+        };
+
+        row.push("source", Value::string(fragment, profiler_span));
+    }
+
+    if let Some(expr_string) = &element.expr {
+        row.push("expr", Value::string(expr_string.clone(), profiler_span));
+    }
+
+    if let Some(val) = &element.element_output {
+        row.push("output", val.clone());
+    }
+
+    row.push(
+        "duration_ms",
+        Value::float(element.duration_sec * 1e3, profiler_span),
+    );
+
+    let mut rows = vec![Value::record(row, profiler_span)];
+
+    for child in &element.children {
+        let child_rows = collect_data(engine_state, profiler, *child, element_id, profiler_span)?;
+        rows.extend(child_rows);
+    }
+
+    Ok(rows)
+}