From 3a1601de8e40eae88cdb7b00a80ee2224c335a3e Mon Sep 17 00:00:00 2001
From: 132ikl <132@ikl.sh>
Date: Thu, 9 Jan 2025 18:09:16 -0500
Subject: [PATCH] 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
> ```
-->

- :green_circle: `toolkit fmt`
- :green_circle: `toolkit clippy`
- :green_circle: `toolkit test`
- :green_circle: `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
---
 crates/nu-command/src/debug/profile.rs      | 15 +++++++--
 crates/nu-protocol/src/debugger/profiler.rs | 34 +++++++++++++++------
 2 files changed, 37 insertions(+), 12 deletions(-)

diff --git a/crates/nu-command/src/debug/profile.rs b/crates/nu-command/src/debug/profile.rs
index 9f72d19d7c..6fe88e2cf2 100644
--- a/crates/nu-command/src/debug/profile.rs
+++ b/crates/nu-command/src/debug/profile.rs
@@ -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(),
         );
diff --git a/crates/nu-protocol/src/debugger/profiler.rs b/crates/nu-protocol/src/debugger/profiler.rs
index 70771ed50b..6ac71f996f 100644
--- a/crates/nu-protocol/src/debugger/profiler.rs
+++ b/crates/nu-protocol/src/debugger/profiler.rs
@@ -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)];