Record and expose perfetto timing traces for inventory collection

Cargo.toml

@@ -144,6 +144,7 @@ members = [
     "package",
     "parallel-task-set",
     "passwords",
+    "perfetto-trace",
     "range-requests",
     "rpaths",
     "sled-agent",
@@ -339,6 +340,7 @@ default-members = [
     "package",
     "parallel-task-set",
     "passwords",
+    "perfetto-trace",
     "range-requests",
     "rpaths",
     "sled-agent",
@@ -728,6 +730,7 @@ partial-io = { version = "0.5.4", features = ["proptest1", "tokio1"] }
 parse-size = "1.1.0"
 paste = "1.0.15"
 percent-encoding = "2.3.1"
+perfetto-trace = { path = "perfetto-trace" }
 peg = "0.8.5"
 pem = "3.0"
 # petname's default features pull in clap for CLI parsing, which we don't need.

dev-tools/omdb/src/bin/omdb/nexus.rs

@@ -68,6 +68,7 @@ use nexus_types::internal_api::background::FmRendezvousStatus;
 use nexus_types::internal_api::background::IncompleteBootstoreConfigReport;
 use nexus_types::internal_api::background::InstanceReincarnationStatus;
 use nexus_types::internal_api::background::InstanceUpdaterStatus;
+use nexus_types::internal_api::background::InventoryCollectionStatus;
 use nexus_types::internal_api::background::InventoryLoadStatus;
 use nexus_types::internal_api::background::LookupRegionPortStatus;
 use nexus_types::internal_api::background::PhysicalDiskAdoptionStatus;
@@ -208,10 +209,23 @@ enum BackgroundTasksCommands {
     Show(BackgroundTasksShowArgs),
     /// Print an event report for a background task if available.
     PrintReport(BackgroundTasksPrintReportArgs),
+    /// Save the last inventory collection's timing trace to a file
+    ///
+    /// The file is in Chrome Trace Event format and can be loaded into
+    /// <https://ui.perfetto.dev/> to visualize where collection time was
+    /// spent.
+    InventoryTrace(BackgroundTasksInventoryTraceArgs),
     /// Activate one or more background tasks
     Activate(BackgroundTasksActivateArgs),
 }
 
+#[derive(Debug, Args)]
+struct BackgroundTasksInventoryTraceArgs {
+    /// where to write the trace JSON
+    #[clap(long)]
+    output: Utf8PathBuf,
+}
+
 #[derive(Debug, Args)]
 struct BackgroundTasksShowArgs {
     /// Names of background tasks to show (default: all)
@@ -746,6 +760,11 @@ impl NexusArgs {
                 )
                 .await
             }
+            NexusCommands::BackgroundTasks(BackgroundTasksArgs {
+                command: BackgroundTasksCommands::InventoryTrace(args),
+            }) => {
+                cmd_nexus_background_tasks_inventory_trace(&client, args).await
+            }
             NexusCommands::BackgroundTasks(BackgroundTasksArgs {
                 command: BackgroundTasksCommands::Activate(args),
             }) => {
@@ -1132,6 +1151,46 @@ async fn cmd_nexus_background_tasks_print_report(
     Ok(())
 }
 
+/// Runs `omdb nexus background-tasks inventory-trace`
+async fn cmd_nexus_background_tasks_inventory_trace(
+    client: &nexus_lockstep_client::Client,
+    args: &BackgroundTasksInventoryTraceArgs,
+) -> Result<(), anyhow::Error> {
+    const TASK_NAME: &str = "inventory_collection";
+    let response = client
+        .bgtask_view(TASK_NAME)
+        .await
+        .context("fetching background task")?;
+    let task = response.into_inner();
+    let LastResult::Completed(last) = task.last else {
+        bail!("task {:?} has never completed", TASK_NAME);
+    };
+    let status: InventoryCollectionStatus =
+        serde_json::from_value(last.details.clone()).with_context(|| {
+            format!(
+                "interpreting task details (did the last activation fail?) \
+                 -- found {:?}",
+                last.details
+            )
+        })?;
+    let Some(trace) = status.trace else {
+        bail!(
+            "task status has no trace (is this Nexus running a version \
+             that records one?)"
+        );
+    };
+    let json =
+        serde_json::to_string_pretty(&trace).context("serializing trace")?;
+    std::fs::write(&args.output, json)
+        .with_context(|| format!("writing {:?}", args.output))?;
+    println!(
+        "wrote trace for collection {} to {}",
+        status.collection_id, args.output
+    );
+    println!("load it into https://ui.perfetto.dev/ to visualize");
+    Ok(())
+}
+
 /// Runs `omdb nexus background-tasks activate`
 async fn cmd_nexus_background_tasks_activate(
     client: &nexus_lockstep_client::Client,
@@ -2195,14 +2254,7 @@ fn print_task_instance_watcher(details: &serde_json::Value) {
 }
 
 fn print_task_inventory_collection(details: &serde_json::Value) {
-    #[derive(Deserialize)]
-    struct InventorySuccess {
-        collection_id: Uuid,
-        time_started: DateTime<Utc>,
-        time_done: DateTime<Utc>,
-    }
-
-    match serde_json::from_value::<InventorySuccess>(details.clone()) {
+    match serde_json::from_value::<InventoryCollectionStatus>(details.clone()) {
         Err(error) => eprintln!(
             "warning: failed to interpret task details: {:?}: {:?}",
             error, details
@@ -2224,6 +2276,20 @@ fn print_task_inventory_collection(details: &serde_json::Value) {
                     .time_done
                     .to_rfc3339_opts(SecondsFormat::Secs, true),
             );
+            if let Some(trace) = &found_inventory.trace {
+                println!("    phase timings:");
+                for event in
+                    trace.trace_events.iter().filter(|e| e.cat == "phase")
+                {
+                    // Bare integer milliseconds: the omdb test output
+                    // redactor recognizes exactly this form.
+                    println!("        {}: {}ms", event.name, event.dur / 1000);
+                }
+                println!(
+                    "    (fetch the full trace with `omdb nexus \
+                     background-tasks inventory-trace`)"
+                );
+            }
         }
     };
 }

dev-tools/omdb/tests/successes.out

@@ -859,6 +859,14 @@ task: "inventory_collection"
     last collection id:      ..........<REDACTED_UUID>...........
     last collection started: <REDACTED_TIMESTAMP>
     last collection done:    <REDACTED_TIMESTAMP>
+    phase timings:
+        mgs: <REDACTED DURATION>ms
+        sled_agents: <REDACTED DURATION>ms
+        keepers: <REDACTED DURATION>ms
+        cockroach: <REDACTED DURATION>ms
+        timesync: <REDACTED DURATION>ms
+        dns_generations: <REDACTED DURATION>ms
+    (fetch the full trace with `omdb nexus background-tasks inventory-trace`)
 
 task: "inventory_loader"
   configured period: every <REDACTED_DURATION>s
@@ -1584,6 +1592,14 @@ task: "inventory_collection"
     last collection id:      ..........<REDACTED_UUID>...........
     last collection started: <REDACTED_TIMESTAMP>
     last collection done:    <REDACTED_TIMESTAMP>
+    phase timings:
+        mgs: <REDACTED DURATION>ms
+        sled_agents: <REDACTED DURATION>ms
+        keepers: <REDACTED DURATION>ms
+        cockroach: <REDACTED DURATION>ms
+        timesync: <REDACTED DURATION>ms
+        dns_generations: <REDACTED DURATION>ms
+    (fetch the full trace with `omdb nexus background-tasks inventory-trace`)
 
 task: "inventory_loader"
   configured period: every <REDACTED_DURATION>s

dev-tools/omdb/tests/usage_errors.out

@@ -1419,12 +1419,13 @@ print information about background tasks
 Usage: omdb nexus background-tasks [OPTIONS] <COMMAND>
 
 Commands:
-  doc           Show documentation about background tasks
-  list          Print a summary of the status of all background tasks
-  show          Print human-readable summary of the status of each background task
-  print-report  Print an event report for a background task if available
-  activate      Activate one or more background tasks
-  help          Print this message or the help of the given subcommand(s)
+  doc              Show documentation about background tasks
+  list             Print a summary of the status of all background tasks
+  show             Print human-readable summary of the status of each background task
+  print-report     Print an event report for a background task if available
+  inventory-trace  Save the last inventory collection's timing trace to a file
+  activate         Activate one or more background tasks
+  help             Print this message or the help of the given subcommand(s)
 
 Options:
       --log-level <LOG_LEVEL>  log level filter [env: LOG_LEVEL=] [default: warn]

nexus/Cargo.toml

@@ -90,6 +90,7 @@ oxql-types.workspace = true
 parallel-task-set.workspace = true
 parse-display.workspace = true
 paste.workspace = true
+perfetto-trace.workspace = true
 # See omicron-rpaths for more about the "pq-sys" dependency.
 pq-sys = "*"
 progenitor-client.workspace = true

nexus/inventory/Cargo.toml

@@ -34,6 +34,7 @@ ntp-admin-client.workspace = true
 omicron-common.workspace = true
 omicron-uuid-kinds.workspace = true
 parallel-task-set.workspace = true
+perfetto-trace.workspace = true
 reqwest.workspace = true
 serde_json.workspace = true
 sled-agent-client.workspace = true