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

nu_protocol/debugger/
profiler.rs
