nu_protocol/debugger/
profiler.rs

1//! Nushell Profiler
2//!
3//! Profiler implements the Debugger trait and can be used via the `debug profile` command for
4//! profiling Nushell code.
5
6use crate::{
7    ast::{Block, Expr, PipelineElement},
8    debugger::Debugger,
9    engine::EngineState,
10    ir::IrBlock,
11    record, PipelineData, ShellError, Span, Value,
12};
13use std::{borrow::Borrow, io::BufRead};
14use web_time::Instant;
15
16#[derive(Debug, Clone, Copy)]
17struct ElementId(usize);
18
19/// Stores profiling information about one pipeline element
20#[derive(Debug, Clone)]
21struct ElementInfo {
22    start: Instant,
23    duration_ns: i64,
24    depth: i64,
25    element_span: Span,
26    element_output: Option<Value>,
27    expr: Option<String>,
28    instruction: Option<(usize, String)>,
29    children: Vec<ElementId>,
30}
31
32impl ElementInfo {
33    pub fn new(depth: i64, element_span: Span) -> Self {
34        ElementInfo {
35            start: Instant::now(),
36            duration_ns: 0,
37            depth,
38            element_span,
39            element_output: None,
40            expr: None,
41            instruction: None,
42            children: vec![],
43        }
44    }
45}
46
47/// Whether [`Profiler`] should report duration as [`Value::Duration`]
48#[derive(Debug, Clone, Copy)]
49pub enum DurationMode {
50    Milliseconds,
51    Value,
52}
53
54/// Options for [`Profiler`]
55#[derive(Debug, Clone)]
56pub struct ProfilerOptions {
57    pub max_depth: i64,
58    pub collect_spans: bool,
59    pub collect_source: bool,
60    pub collect_expanded_source: bool,
61    pub collect_values: bool,
62    pub collect_exprs: bool,
63    pub collect_instructions: bool,
64    pub collect_lines: bool,
65    pub duration_mode: DurationMode,
66}
67
68/// Basic profiler, used in `debug profile`
69#[derive(Debug, Clone)]
70pub struct Profiler {
71    depth: i64,
72    opts: ProfilerOptions,
73    elements: Vec<ElementInfo>,
74    element_stack: Vec<ElementId>,
75}
76
77impl Profiler {
78    #[allow(clippy::too_many_arguments)]
79    pub fn new(opts: ProfilerOptions, span: Span) -> Self {
80        let first = ElementInfo {
81            start: Instant::now(),
82            duration_ns: 0,
83            depth: 0,
84            element_span: span,
85            element_output: opts.collect_values.then(|| Value::nothing(span)),
86            expr: opts.collect_exprs.then(|| "call".to_string()),
87            instruction: opts
88                .collect_instructions
89                .then(|| (0, "<start>".to_string())),
90            children: vec![],
91        };
92
93        Profiler {
94            depth: 0,
95            opts,
96            elements: vec![first],
97            element_stack: vec![ElementId(0)],
98        }
99    }
100
101    fn last_element_id(&self) -> Option<ElementId> {
102        self.element_stack.last().copied()
103    }
104
105    fn last_element_mut(&mut self) -> Option<&mut ElementInfo> {
106        self.last_element_id()
107            .and_then(|id| self.elements.get_mut(id.0))
108    }
109}
110
111impl Debugger for Profiler {
112    fn activate(&mut self) {
113        let Some(root_element) = self.last_element_mut() else {
114            eprintln!("Profiler Error: Missing root element.");
115            return;
116        };
117
118        root_element.start = Instant::now();
119    }
120
121    fn deactivate(&mut self) {
122        let Some(root_element) = self.last_element_mut() else {
123            eprintln!("Profiler Error: Missing root element.");
124            return;
125        };
126
127        root_element.duration_ns = root_element.start.elapsed().as_nanos() as i64;
128    }
129
130    fn enter_block(&mut self, _engine_state: &EngineState, _block: &Block) {
131        self.depth += 1;
132    }
133
134    fn leave_block(&mut self, _engine_state: &EngineState, _block: &Block) {
135        self.depth -= 1;
136    }
137
138    fn enter_element(&mut self, engine_state: &EngineState, element: &PipelineElement) {
139        if self.depth > self.opts.max_depth {
140            return;
141        }
142
143        let Some(parent_id) = self.last_element_id() else {
144            eprintln!("Profiler Error: Missing parent element ID.");
145            return;
146        };
147
148        let expr_opt = self
149            .opts
150            .collect_exprs
151            .then(|| expr_to_string(engine_state, &element.expr.expr));
152
153        let new_id = ElementId(self.elements.len());
154
155        let mut new_element = ElementInfo::new(self.depth, element.expr.span);
156        new_element.expr = expr_opt;
157
158        self.elements.push(new_element);
159
160        let Some(parent) = self.elements.get_mut(parent_id.0) else {
161            eprintln!("Profiler Error: Missing parent element.");
162            return;
163        };
164
165        parent.children.push(new_id);
166        self.element_stack.push(new_id);
167    }
168
169    fn leave_element(
170        &mut self,
171        _engine_state: &EngineState,
172        element: &PipelineElement,
173        result: &Result<PipelineData, ShellError>,
174    ) {
175        if self.depth > self.opts.max_depth {
176            return;
177        }
178
179        let element_span = element.expr.span;
180
181        let out_opt = self.opts.collect_values.then(|| match result {
182            Ok(pipeline_data) => match pipeline_data {
183                PipelineData::Value(val, ..) => val.clone(),
184                PipelineData::ListStream(..) => Value::string("list stream", element_span),
185                PipelineData::ByteStream(..) => Value::string("byte stream", element_span),
186                _ => Value::nothing(element_span),
187            },
188            Err(e) => Value::error(e.clone(), element_span),
189        });
190
191        let Some(last_element) = self.last_element_mut() else {
192            eprintln!("Profiler Error: Missing last element.");
193            return;
194        };
195
196        last_element.duration_ns = last_element.start.elapsed().as_nanos() as i64;
197        last_element.element_output = out_opt;
198
199        self.element_stack.pop();
200    }
201
202    fn enter_instruction(
203        &mut self,
204        engine_state: &EngineState,
205        ir_block: &IrBlock,
206        instruction_index: usize,
207        _registers: &[PipelineData],
208    ) {
209        if self.depth > self.opts.max_depth {
210            return;
211        }
212
213        let Some(parent_id) = self.last_element_id() else {
214            eprintln!("Profiler Error: Missing parent element ID.");
215            return;
216        };
217
218        let instruction = &ir_block.instructions[instruction_index];
219        let span = ir_block.spans[instruction_index];
220
221        let instruction_opt = self.opts.collect_instructions.then(|| {
222            (
223                instruction_index,
224                instruction
225                    .display(engine_state, &ir_block.data)
226                    .to_string(),
227            )
228        });
229
230        let new_id = ElementId(self.elements.len());
231
232        let mut new_element = ElementInfo::new(self.depth, span);
233        new_element.instruction = instruction_opt;
234
235        self.elements.push(new_element);
236
237        let Some(parent) = self.elements.get_mut(parent_id.0) else {
238            eprintln!("Profiler Error: Missing parent element.");
239            return;
240        };
241
242        parent.children.push(new_id);
243        self.element_stack.push(new_id);
244    }
245
246    fn leave_instruction(
247        &mut self,
248        _engine_state: &EngineState,
249        ir_block: &IrBlock,
250        instruction_index: usize,
251        registers: &[PipelineData],
252        error: Option<&ShellError>,
253    ) {
254        if self.depth > self.opts.max_depth {
255            return;
256        }
257
258        let instruction = &ir_block.instructions[instruction_index];
259        let span = ir_block.spans[instruction_index];
260
261        let out_opt = self
262            .opts
263            .collect_values
264            .then(|| {
265                error
266                    .map(Err)
267                    .or_else(|| {
268                        instruction
269                            .output_register()
270                            .map(|register| Ok(&registers[register.get() as usize]))
271                    })
272                    .map(|result| format_result(&result, span))
273            })
274            .flatten();
275
276        let Some(last_element) = self.last_element_mut() else {
277            eprintln!("Profiler Error: Missing last element.");
278            return;
279        };
280
281        last_element.duration_ns = last_element.start.elapsed().as_nanos() as i64;
282        last_element.element_output = out_opt;
283
284        self.element_stack.pop();
285    }
286
287    fn report(&self, engine_state: &EngineState, profiler_span: Span) -> Result<Value, ShellError> {
288        Ok(Value::list(
289            collect_data(
290                engine_state,
291                self,
292                ElementId(0),
293                ElementId(0),
294                profiler_span,
295            )?,
296            profiler_span,
297        ))
298    }
299}
300
301fn profiler_error(msg: impl Into<String>, span: Span) -> ShellError {
302    ShellError::GenericError {
303        error: "Profiler Error".to_string(),
304        msg: msg.into(),
305        span: Some(span),
306        help: None,
307        inner: vec![],
308    }
309}
310
311fn expr_to_string(engine_state: &EngineState, expr: &Expr) -> String {
312    match expr {
313        Expr::AttributeBlock(ab) => expr_to_string(engine_state, &ab.item.expr),
314        Expr::Binary(_) => "binary".to_string(),
315        Expr::BinaryOp(_, _, _) => "binary operation".to_string(),
316        Expr::Block(_) => "block".to_string(),
317        Expr::Bool(_) => "bool".to_string(),
318        Expr::Call(call) => {
319            let decl = engine_state.get_decl(call.decl_id);
320            if decl.name() == "collect" && call.head == Span::new(0, 0) {
321                "call (implicit collect)"
322            } else {
323                "call"
324            }
325            .to_string()
326        }
327        Expr::CellPath(_) => "cell path".to_string(),
328        Expr::Closure(_) => "closure".to_string(),
329        Expr::DateTime(_) => "datetime".to_string(),
330        Expr::Directory(_, _) => "directory".to_string(),
331        Expr::ExternalCall(_, _) => "external call".to_string(),
332        Expr::Filepath(_, _) => "filepath".to_string(),
333        Expr::Float(_) => "float".to_string(),
334        Expr::FullCellPath(full_cell_path) => {
335            let head = expr_to_string(engine_state, &full_cell_path.head.expr);
336            format!("full cell path ({head})")
337        }
338        Expr::Garbage => "garbage".to_string(),
339        Expr::GlobPattern(_, _) => "glob pattern".to_string(),
340        Expr::ImportPattern(_) => "import pattern".to_string(),
341        Expr::Int(_) => "int".to_string(),
342        Expr::Keyword(_) => "keyword".to_string(),
343        Expr::List(_) => "list".to_string(),
344        Expr::MatchBlock(_) => "match block".to_string(),
345        Expr::Nothing => "nothing".to_string(),
346        Expr::Operator(_) => "operator".to_string(),
347        Expr::Overlay(_) => "overlay".to_string(),
348        Expr::Range(_) => "range".to_string(),
349        Expr::Record(_) => "record".to_string(),
350        Expr::RowCondition(_) => "row condition".to_string(),
351        Expr::Signature(_) => "signature".to_string(),
352        Expr::String(_) | Expr::RawString(_) => "string".to_string(),
353        Expr::StringInterpolation(_) => "string interpolation".to_string(),
354        Expr::GlobInterpolation(_, _) => "glob interpolation".to_string(),
355        Expr::Collect(_, _) => "collect".to_string(),
356        Expr::Subexpression(_) => "subexpression".to_string(),
357        Expr::Table(_) => "table".to_string(),
358        Expr::UnaryNot(_) => "unary not".to_string(),
359        Expr::ValueWithUnit(_) => "value with unit".to_string(),
360        Expr::Var(_) => "var".to_string(),
361        Expr::VarDecl(_) => "var decl".to_string(),
362    }
363}
364
365fn format_result(
366    result: &Result<impl Borrow<PipelineData>, impl Borrow<ShellError>>,
367    element_span: Span,
368) -> Value {
369    match result {
370        Ok(pipeline_data) => match pipeline_data.borrow() {
371            PipelineData::Value(val, ..) => val.clone(),
372            PipelineData::ListStream(..) => Value::string("list stream", element_span),
373            PipelineData::ByteStream(..) => Value::string("byte stream", element_span),
374            _ => Value::nothing(element_span),
375        },
376        Err(e) => Value::error(e.borrow().clone(), element_span),
377    }
378}
379
380// Find a file name and a line number (indexed from 1) of a span
381fn find_file_of_span(engine_state: &EngineState, span: Span) -> Option<(&str, usize)> {
382    for file in engine_state.files() {
383        if file.covered_span.contains_span(span) {
384            // count the number of lines between file start and the searched span start
385            let chunk =
386                engine_state.get_span_contents(Span::new(file.covered_span.start, span.start));
387            let nlines = chunk.lines().count();
388            // account for leading part of current line being counted as a separate line
389            let line_num = if chunk.last() == Some(&b'\n') {
390                nlines + 1
391            } else {
392                nlines
393            };
394
395            // first line has no previous line, clamp up to `1`
396            let line_num = usize::max(line_num, 1);
397
398            return Some((&file.name, line_num));
399        }
400    }
401
402    None
403}
404
405fn collect_data(
406    engine_state: &EngineState,
407    profiler: &Profiler,
408    element_id: ElementId,
409    parent_id: ElementId,
410    profiler_span: Span,
411) -> Result<Vec<Value>, ShellError> {
412    let element = &profiler.elements[element_id.0];
413
414    let mut row = record! {
415        "depth" => Value::int(element.depth, profiler_span),
416        "id" => Value::int(element_id.0 as i64, profiler_span),
417        "parent_id" => Value::int(parent_id.0 as i64, profiler_span),
418    };
419
420    if profiler.opts.collect_lines {
421        if let Some((fname, line_num)) = find_file_of_span(engine_state, element.element_span) {
422            row.push("file", Value::string(fname, profiler_span));
423            row.push("line", Value::int(line_num as i64, profiler_span));
424        } else {
425            row.push("file", Value::nothing(profiler_span));
426            row.push("line", Value::nothing(profiler_span));
427        }
428    }
429
430    if profiler.opts.collect_spans {
431        let span_start = i64::try_from(element.element_span.start)
432            .map_err(|_| profiler_error("error converting span start to i64", profiler_span))?;
433        let span_end = i64::try_from(element.element_span.end)
434            .map_err(|_| profiler_error("error converting span end to i64", profiler_span))?;
435
436        row.push(
437            "span",
438            Value::record(
439                record! {
440                    "start" => Value::int(span_start, profiler_span),
441                    "end" => Value::int(span_end, profiler_span),
442                },
443                profiler_span,
444            ),
445        );
446    }
447
448    if profiler.opts.collect_source {
449        let val = String::from_utf8_lossy(engine_state.get_span_contents(element.element_span));
450        let val = val.trim();
451        let nlines = val.lines().count();
452
453        let fragment = if profiler.opts.collect_expanded_source {
454            val.to_string()
455        } else {
456            let mut first_line = val.lines().next().unwrap_or("").to_string();
457
458            if nlines > 1 {
459                first_line.push_str(" ...");
460            }
461
462            first_line
463        };
464
465        row.push("source", Value::string(fragment, profiler_span));
466    }
467
468    if let Some(expr_string) = &element.expr {
469        row.push("expr", Value::string(expr_string.clone(), profiler_span));
470    }
471
472    if let Some((instruction_index, instruction)) = &element.instruction {
473        row.push(
474            "pc",
475            (*instruction_index)
476                .try_into()
477                .map(|index| Value::int(index, profiler_span))
478                .unwrap_or(Value::nothing(profiler_span)),
479        );
480        row.push("instruction", Value::string(instruction, profiler_span));
481    }
482
483    if let Some(val) = &element.element_output {
484        row.push("output", val.clone());
485    }
486
487    match profiler.opts.duration_mode {
488        DurationMode::Milliseconds => {
489            let val = Value::float(element.duration_ns as f64 / 1000.0 / 1000.0, profiler_span);
490            row.push("duration_ms", val);
491        }
492        DurationMode::Value => {
493            let val = Value::duration(element.duration_ns, profiler_span);
494            row.push("duration", val);
495        }
496    };
497
498    let mut rows = vec![Value::record(row, profiler_span)];
499
500    for child in &element.children {
501        let child_rows = collect_data(engine_state, profiler, *child, element_id, profiler_span)?;
502        rows.extend(child_rows);
503    }
504
505    Ok(rows)
506}
nu_protocol/debugger/profiler.rs

nu_protocol/debugger/
profiler.rs
