Add flag to debug profile to output duration field as Value::Duration (#14749)

<!--
if this PR closes one or more issues, you can automatically link the PR
with
them by using one of the [*linking
keywords*](https://docs.github.com/en/issues/tracking-your-work-with-issues/linking-a-pull-request-to-an-issue#linking-a-pull-request-to-an-issue-using-a-keyword),
e.g.
- this PR should close #xxxx
- fixes #xxxx

you can also mention related issues, PRs or discussions!
-->

# Description
<!--
Thank you for improving Nushell. Please, check our [contributing
guide](../CONTRIBUTING.md) and talk to the core team before making major
changes.

Description of your pull request goes here. **Provide examples and/or
screenshots** if your changes affect the user experience.
-->

This PR adds a flag to `debug profile` to output the duration field as
Value::Duration. Without the flag, the behavior is same as before: a
column named `duration_ms` which is `Value::Float`. With the flag, there
is instead a column named just `duration` which is `Value::Duration`.
Additionally, this PR changes the time tracking to use nanoseconds
instead of float seconds, so it can be output as either milliseconds or
`Duration` (which uses nanoseconds internally). I don't think overflow
is a concern here, because the maximum amount of time a `Duration` can
store is over 292 years, and if a Nushell instruction takes longer than
that to run then I think we might have bigger issues.

# User-Facing Changes
<!-- List of all changes that impact the user experience here. This
helps us keep track of breaking changes. -->

* Adds a flag `--duration-values` to `debug profile` which the
`duration_ms` field in `debug profile` to a `duration` field which uses
proper `duration` values.

# Tests + Formatting
<!--
Don't forget to add tests that cover your changes.

Make sure you've run and fixed any issues with these commands:

- `cargo fmt --all -- --check` to check standard code formatting (`cargo
fmt --all` applies these changes)
- `cargo clippy --workspace -- -D warnings -D clippy::unwrap_used` to
check that you're using the standard code style
- `cargo test --workspace` to check that all tests pass (on Windows make
sure to [enable developer
mode](https://learn.microsoft.com/en-us/windows/apps/get-started/developer-mode-features-and-debugging))
- `cargo run -- -c "use toolkit.nu; toolkit test stdlib"` to run the
tests for the standard library

> **Note**
> from `nushell` you can also use the `toolkit` as follows
> ```bash
> use toolkit.nu # or use an `env_change` hook to activate it
automatically
> toolkit check pr
> ```
-->

- 🟢 `toolkit fmt`
- 🟢 `toolkit clippy`
- 🟢 `toolkit test`
- 🟢 `toolkit test stdlib`

# After Submitting
<!-- If your PR had any user-facing changes, update [the
documentation](https://github.com/nushell/nushell.github.io) after the
PR is merged, if necessary. This will help us keep the docs up to date.
-->
N/A
This commit is contained in:
132ikl 2025-01-09 18:09:16 -05:00 committed by GitHub
parent 3f8dd1b705
commit 3a1601de8e
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
2 changed files with 37 additions and 12 deletions

View File

@ -1,6 +1,6 @@
use nu_engine::{command_prelude::*, ClosureEvalOnce};
use nu_protocol::{
debugger::{Profiler, ProfilerOptions},
debugger::{DurationMode, Profiler, ProfilerOptions},
engine::Closure,
};
@ -31,6 +31,11 @@ impl Command for DebugProfile {
Some('v'),
)
.switch("lines", "Collect line numbers", Some('l'))
.switch(
"duration-values",
"Report instruction duration as duration values rather than milliseconds",
Some('d'),
)
.named(
"max-depth",
SyntaxShape::Int,
@ -59,7 +64,7 @@ The output can be heavily customized. By default, the following columns are incl
be shown with the --expand-source flag.
- pc : The index of the instruction within the block.
- instruction : The pretty printed instruction being evaluated.
- duration_ms : How long it took to run the instruction in milliseconds.
- duration : How long it took to run the instruction.
- (optional) span : Span associated with the instruction. Can be viewed via the `view span`
command. Enabled with the --spans flag.
- (optional) output : The output value of the instruction. Enabled with the --values flag.
@ -108,10 +113,15 @@ confusing the id/parent_id hierarchy. The --expr flag is helpful for investigati
let collect_expanded_source = call.has_flag(engine_state, stack, "expanded-source")?;
let collect_values = call.has_flag(engine_state, stack, "values")?;
let collect_lines = call.has_flag(engine_state, stack, "lines")?;
let duration_values = call.has_flag(engine_state, stack, "duration-values")?;
let max_depth = call
.get_flag(engine_state, stack, "max-depth")?
.unwrap_or(2);
let duration_mode = match duration_values {
true => DurationMode::Value,
false => DurationMode::Milliseconds,
};
let profiler = Profiler::new(
ProfilerOptions {
max_depth,
@ -122,6 +132,7 @@ confusing the id/parent_id hierarchy. The --expr flag is helpful for investigati
collect_exprs: false,
collect_instructions: true,
collect_lines,
duration_mode,
},
call.span(),
);

View File

@ -20,7 +20,7 @@ struct ElementId(usize);
#[derive(Debug, Clone)]
struct ElementInfo {
start: Instant,
duration_sec: f64,
duration_ns: i64,
depth: i64,
element_span: Span,
element_output: Option<Value>,
@ -33,7 +33,7 @@ impl ElementInfo {
pub fn new(depth: i64, element_span: Span) -> Self {
ElementInfo {
start: Instant::now(),
duration_sec: 0.0,
duration_ns: 0,
depth,
element_span,
element_output: None,
@ -44,6 +44,13 @@ impl ElementInfo {
}
}
/// Whether [`Profiler`] should report duration as [`Value::Duration`]
#[derive(Debug, Clone, Copy)]
pub enum DurationMode {
Milliseconds,
Value,
}
/// Options for [`Profiler`]
#[derive(Debug, Clone)]
pub struct ProfilerOptions {
@ -55,6 +62,7 @@ pub struct ProfilerOptions {
pub collect_exprs: bool,
pub collect_instructions: bool,
pub collect_lines: bool,
pub duration_mode: DurationMode,
}
/// Basic profiler, used in `debug profile`
@ -71,7 +79,7 @@ impl Profiler {
pub fn new(opts: ProfilerOptions, span: Span) -> Self {
let first = ElementInfo {
start: Instant::now(),
duration_sec: 0.0,
duration_ns: 0,
depth: 0,
element_span: span,
element_output: opts.collect_values.then(|| Value::nothing(span)),
@ -116,7 +124,7 @@ impl Debugger for Profiler {
return;
};
root_element.duration_sec = root_element.start.elapsed().as_secs_f64();
root_element.duration_ns = root_element.start.elapsed().as_nanos() as i64;
}
fn enter_block(&mut self, _engine_state: &EngineState, _block: &Block) {
@ -185,7 +193,7 @@ impl Debugger for Profiler {
return;
};
last_element.duration_sec = last_element.start.elapsed().as_secs_f64();
last_element.duration_ns = last_element.start.elapsed().as_nanos() as i64;
last_element.element_output = out_opt;
self.element_stack.pop();
@ -270,7 +278,7 @@ impl Debugger for Profiler {
return;
};
last_element.duration_sec = last_element.start.elapsed().as_secs_f64();
last_element.duration_ns = last_element.start.elapsed().as_nanos() as i64;
last_element.element_output = out_opt;
self.element_stack.pop();
@ -475,10 +483,16 @@ fn collect_data(
row.push("output", val.clone());
}
row.push(
"duration_ms",
Value::float(element.duration_sec * 1e3, profiler_span),
);
match profiler.opts.duration_mode {
DurationMode::Milliseconds => {
let val = Value::float(element.duration_ns as f64 / 1000.0 / 1000.0, profiler_span);
row.push("duration_ms", val);
}
DurationMode::Value => {
let val = Value::duration(element.duration_ns, profiler_span);
row.push("duration", val);
}
};
let mut rows = vec![Value::record(row, profiler_span)];