1use nu_engine::{ClosureEvalOnce, command_prelude::*};
2use nu_protocol::{
3 debugger::{DurationMode, Profiler, ProfilerOptions},
4 engine::Closure,
5};
6
7#[derive(Clone)]
8pub struct DebugProfile;
9
10impl Command for DebugProfile {
11 fn name(&self) -> &str {
12 "debug profile"
13 }
14
15 fn signature(&self) -> nu_protocol::Signature {
16 Signature::build("debug profile")
17 .required(
18 "closure",
19 SyntaxShape::Closure(None),
20 "The closure to profile.",
21 )
22 .switch("spans", "Collect spans of profiled elements", Some('s'))
23 .switch(
24 "expand-source",
25 "Collect full source fragments of profiled elements",
26 Some('e'),
27 )
28 .switch(
29 "values",
30 "Collect pipeline element output values",
31 Some('v'),
32 )
33 .switch("lines", "Collect line numbers", Some('l'))
34 .switch(
35 "duration-values",
36 "Report instruction duration as duration values rather than milliseconds",
37 Some('d'),
38 )
39 .named(
40 "max-depth",
41 SyntaxShape::Int,
42 "How many blocks/closures deep to step into (default 2)",
43 Some('m'),
44 )
45 .input_output_types(vec![(Type::Any, Type::table())])
46 .category(Category::Debug)
47 }
48
49 fn description(&self) -> &str {
50 "Profile pipeline elements in a closure."
51 }
52
53 fn extra_description(&self) -> &str {
54 r#"The profiler profiles every evaluated instruction inside a closure, stepping into all
55commands calls and other blocks/closures.
56
57The output can be heavily customized. By default, the following columns are included:
58- depth : Depth of the instruction. Each entered block adds one level of depth. How many
59 blocks deep to step into is controlled with the --max-depth option.
60- id : ID of the instruction
61- parent_id : ID of the instruction that created the parent scope
62- source : Source code that generated the instruction. If the source code has multiple lines,
63 only the first line is used and `...` is appended to the end. Full source code can
64 be shown with the --expand-source flag.
65- pc : The index of the instruction within the block.
66- instruction : The pretty printed instruction being evaluated.
67- duration : How long it took to run the instruction.
68- (optional) span : Span associated with the instruction. Can be viewed via the `view span`
69 command. Enabled with the --spans flag.
70- (optional) output : The output value of the instruction. Enabled with the --values flag.
71
72To illustrate the depth and IDs, consider `debug profile { do { if true { echo 'spam' } } }`. A unique ID is generated each time an instruction is executed, and there are two levels of depth:
73
74```
75depth id parent_id source pc instruction
76 0 0 0 debug profile { do { if true { 'spam' } } } 0 <start>
77 1 1 0 { if true { 'spam' } } 0 load-literal %1, closure(2164)
78 1 2 0 { if true { 'spam' } } 1 push-positional %1
79 1 3 0 { do { if true { 'spam' } } } 2 redirect-out caller
80 1 4 0 { do { if true { 'spam' } } } 3 redirect-err caller
81 1 5 0 do 4 call decl 7 "do", %0
82 2 6 5 true 0 load-literal %1, bool(true)
83 2 7 5 if 1 not %1
84 2 8 5 if 2 branch-if %1, 5
85 2 9 5 'spam' 3 load-literal %0, string("spam")
86 2 10 5 if 4 jump 6
87 2 11 5 { if true { 'spam' } } 6 return %0
88 1 12 0 { do { if true { 'spam' } } } 5 return %0
89```
90
91Each block entered increments depth by 1 and each block left decrements it by one. This way you can
92control the profiling granularity. Passing --max-depth=1 to the above would stop inside the `do`
93at `if true { 'spam' }`. The id is used to identify each element. The parent_id tells you that the
94instructions inside the block are being executed because of `do` (5), which in turn was spawned from
95the root `debug profile { ... }`.
96
97For a better understanding of how instructions map to source code, see the `view ir` command.
98
99Note: In some cases, the ordering of pipeline elements might not be intuitive. For example,
100`[ a bb cc ] | each { $in | str length }` involves some implicit collects and lazy evaluation
101confusing the id/parent_id hierarchy. The --expr flag is helpful for investigating these issues."#
102 }
103
104 fn run(
105 &self,
106 engine_state: &EngineState,
107 stack: &mut Stack,
108 call: &Call,
109 input: PipelineData,
110 ) -> Result<PipelineData, ShellError> {
111 let closure: Closure = call.req(engine_state, stack, 0)?;
112 let collect_spans = call.has_flag(engine_state, stack, "spans")?;
113 let collect_expanded_source = call.has_flag(engine_state, stack, "expanded-source")?;
114 let collect_values = call.has_flag(engine_state, stack, "values")?;
115 let collect_lines = call.has_flag(engine_state, stack, "lines")?;
116 let duration_values = call.has_flag(engine_state, stack, "duration-values")?;
117 let max_depth = call
118 .get_flag(engine_state, stack, "max-depth")?
119 .unwrap_or(2);
120
121 let duration_mode = match duration_values {
122 true => DurationMode::Value,
123 false => DurationMode::Milliseconds,
124 };
125 let profiler = Profiler::new(
126 ProfilerOptions {
127 max_depth,
128 collect_spans,
129 collect_source: true,
130 collect_expanded_source,
131 collect_values,
132 collect_exprs: false,
133 collect_instructions: true,
134 collect_lines,
135 duration_mode,
136 },
137 call.span(),
138 );
139
140 let lock_err = |_| ShellError::GenericError {
141 error: "Profiler Error".to_string(),
142 msg: "could not lock debugger, poisoned mutex".to_string(),
143 span: Some(call.head),
144 help: None,
145 inner: vec![],
146 };
147
148 engine_state
149 .activate_debugger(Box::new(profiler))
150 .map_err(lock_err)?;
151
152 let result = ClosureEvalOnce::new(engine_state, stack, closure).run_with_input(input);
153
154 let pipeline_data = result?;
156
157 let _ = pipeline_data.into_value(call.span());
159
160 Ok(engine_state
161 .deactivate_debugger()
162 .map_err(lock_err)?
163 .report(engine_state, call.span())?
164 .into_pipeline_data())
165 }
166
167 fn examples(&self) -> Vec<Example> {
168 vec![
169 Example {
170 description: "Profile config evaluation",
171 example: "debug profile { source $nu.config-path }",
172 result: None,
173 },
174 Example {
175 description: "Profile config evaluation with more granularity",
176 example: "debug profile { source $nu.config-path } --max-depth 4",
177 result: None,
178 },
179 ]
180 }
181}