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, Stack},
11    ir::IrBlock,
12    record,
13    shell_error::generic::GenericError,
14};
15use nu_utils::time::Instant;
16use std::{
17    borrow::{Borrow, Cow},
18    io::BufRead,
19};
20
21#[derive(Debug, Clone, Copy)]
22struct ElementId(usize);
23
24/// Stores profiling information about one pipeline element
25#[derive(Debug, Clone)]
26struct ElementInfo {
27    start: Instant,
28    duration_ns: i64,
29    depth: i64,
30    element_span: Span,
31    element_output: Option<Value>,
32    expr: Option<String>,
33    instruction: Option<(usize, String)>,
34    children: Vec<ElementId>,
35}
36
37impl ElementInfo {
38    pub fn new(depth: i64, element_span: Span) -> Self {
39        ElementInfo {
40            start: Instant::now(),
41            duration_ns: 0,
42            depth,
43            element_span,
44            element_output: None,
45            expr: None,
46            instruction: None,
47            children: vec![],
48        }
49    }
50}
51
52/// Whether [`Profiler`] should report duration as [`Value::Duration`]
53#[derive(Debug, Clone, Copy)]
54pub enum DurationMode {
55    Milliseconds,
56    Value,
57}
58
59/// Options for [`Profiler`]
60#[derive(Debug, Clone)]
61pub struct ProfilerOptions {
62    pub max_depth: i64,
63    pub collect_spans: bool,
64    pub collect_source: bool,
65    pub collect_expanded_source: bool,
66    pub collect_values: bool,
67    pub collect_exprs: bool,
68    pub collect_instructions: bool,
69    pub collect_lines: bool,
70    pub duration_mode: DurationMode,
71}
72
73/// Basic profiler, used in `debug profile`
74#[derive(Debug, Clone)]
75pub struct Profiler {
76    depth: i64,
77    opts: ProfilerOptions,
78    elements: Vec<ElementInfo>,
79    element_stack: Vec<ElementId>,
80}
81
82impl Profiler {
83    #[allow(clippy::too_many_arguments)]
84    pub fn new(opts: ProfilerOptions, span: Span) -> Self {
85        let first = ElementInfo {
86            start: Instant::now(),
87            duration_ns: 0,
88            depth: 0,
89            element_span: span,
90            element_output: opts.collect_values.then(|| Value::nothing(span)),
91            expr: opts.collect_exprs.then(|| "call".to_string()),
92            instruction: opts
93                .collect_instructions
94                .then(|| (0, "<start>".to_string())),
95            children: vec![],
96        };
97
98        Profiler {
99            depth: 0,
100            opts,
101            elements: vec![first],
102            element_stack: vec![ElementId(0)],
103        }
104    }
105
106    fn last_element_id(&self) -> Option<ElementId> {
107        self.element_stack.last().copied()
108    }
109
110    fn last_element_mut(&mut self) -> Option<&mut ElementInfo> {
111        self.last_element_id()
112            .and_then(|id| self.elements.get_mut(id.0))
113    }
114}
115
116impl Debugger for Profiler {
117    fn activate(&mut self) {
118        let Some(root_element) = self.last_element_mut() else {
119            eprintln!("Profiler Error: Missing root element.");
120            return;
121        };
122
123        root_element.start = Instant::now();
124    }
125
126    fn deactivate(&mut self) {
127        let Some(root_element) = self.last_element_mut() else {
128            eprintln!("Profiler Error: Missing root element.");
129            return;
130        };
131
132        root_element.duration_ns = root_element.start.elapsed().as_nanos() as i64;
133    }
134
135    fn enter_block(&mut self, _engine_state: &EngineState, _block: &Block) {
136        self.depth += 1;
137    }
138
139    fn leave_block(&mut self, _engine_state: &EngineState, _block: &Block) {
140        self.depth -= 1;
141    }
142
143    fn enter_element(&mut self, engine_state: &EngineState, element: &PipelineElement) {
144        if self.depth > self.opts.max_depth {
145            return;
146        }
147
148        let Some(parent_id) = self.last_element_id() else {
149            eprintln!("Profiler Error: Missing parent element ID.");
150            return;
151        };
152
153        let expr_opt = self
154            .opts
155            .collect_exprs
156            .then(|| expr_to_string(engine_state, &element.expr.expr));
157
158        let new_id = ElementId(self.elements.len());
159
160        let mut new_element = ElementInfo::new(self.depth, element.expr.span);
161        new_element.expr = expr_opt;
162
163        self.elements.push(new_element);
164
165        let Some(parent) = self.elements.get_mut(parent_id.0) else {
166            eprintln!("Profiler Error: Missing parent element.");
167            return;
168        };
169
170        parent.children.push(new_id);
171        self.element_stack.push(new_id);
172    }
173
174    fn leave_element(
175        &mut self,
176        _engine_state: &EngineState,
177        element: &PipelineElement,
178        result: &Result<PipelineData, ShellError>,
179    ) {
180        if self.depth > self.opts.max_depth {
181            return;
182        }
183
184        let element_span = element.expr.span;
185
186        let out_opt = self.opts.collect_values.then(|| match result {
187            Ok(pipeline_data) => match pipeline_data {
188                PipelineData::Value(val, ..) => val.clone(),
189                PipelineData::ListStream(..) => Value::string("list stream", element_span),
190                PipelineData::ByteStream(..) => Value::string("byte stream", element_span),
191                _ => Value::nothing(element_span),
192            },
193            Err(e) => Value::error(e.clone(), element_span),
194        });
195
196        let Some(last_element) = self.last_element_mut() else {
197            eprintln!("Profiler Error: Missing last element.");
198            return;
199        };
200
201        last_element.duration_ns = last_element.start.elapsed().as_nanos() as i64;
202        last_element.element_output = out_opt;
203
204        self.element_stack.pop();
205    }
206
207    fn enter_instruction(
208        &mut self,
209        engine_state: &EngineState,
210        _stack: &Stack,
211        ir_block: &IrBlock,
212        instruction_index: usize,
213        _registers: &[PipelineExecutionData],
214    ) {
215        if self.depth > self.opts.max_depth {
216            return;
217        }
218
219        let Some(parent_id) = self.last_element_id() else {
220            eprintln!("Profiler Error: Missing parent element ID.");
221            return;
222        };
223
224        let instruction = &ir_block.instructions[instruction_index];
225        let span = ir_block.spans[instruction_index];
226
227        let instruction_opt = self.opts.collect_instructions.then(|| {
228            (
229                instruction_index,
230                instruction
231                    .display(engine_state, &ir_block.data)
232                    .to_string(),
233            )
234        });
235
236        let new_id = ElementId(self.elements.len());
237
238        let mut new_element = ElementInfo::new(self.depth, span);
239        new_element.instruction = instruction_opt;
240
241        self.elements.push(new_element);
242
243        let Some(parent) = self.elements.get_mut(parent_id.0) else {
244            eprintln!("Profiler Error: Missing parent element.");
245            return;
246        };
247
248        parent.children.push(new_id);
249        self.element_stack.push(new_id);
250    }
251
252    fn leave_instruction(
253        &mut self,
254        _engine_state: &EngineState,
255        _stack: &Stack,
256        ir_block: &IrBlock,
257        instruction_index: usize,
258        registers: &[PipelineExecutionData],
259        error: Option<&ShellError>,
260    ) {
261        if self.depth > self.opts.max_depth {
262            return;
263        }
264
265        let instruction = &ir_block.instructions[instruction_index];
266        let span = ir_block.spans[instruction_index];
267
268        let out_opt = self
269            .opts
270            .collect_values
271            .then(|| {
272                error
273                    .map(Err)
274                    .or_else(|| {
275                        instruction
276                            .output_register()
277                            .map(|register| Ok(&registers[register.get() as usize]))
278                    })
279                    .map(|result| format_result(result.map(|r| &r.body), span))
280            })
281            .flatten();
282
283        let Some(last_element) = self.last_element_mut() else {
284            eprintln!("Profiler Error: Missing last element.");
285            return;
286        };
287
288        last_element.duration_ns = last_element.start.elapsed().as_nanos() as i64;
289        last_element.element_output = out_opt;
290
291        self.element_stack.pop();
292    }
293
294    fn report(&self, engine_state: &EngineState, profiler_span: Span) -> Result<Value, ShellError> {
295        Ok(Value::list(
296            collect_data(
297                engine_state,
298                self,
299                ElementId(0),
300                ElementId(0),
301                profiler_span,
302            )?,
303            profiler_span,
304        ))
305    }
306}
307
308fn profiler_error(msg: impl Into<Cow<'static, str>>, span: Span) -> ShellError {
309    ShellError::Generic(GenericError::new("Profiler Error", msg, span))
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
