From 132949078b919c6f07aba83bb53fe45eb403a32d Mon Sep 17 00:00:00 2001 From: Sean Klein Date: Thu, 6 Aug 2026 15:34:09 -0700 Subject: [PATCH 1/3] Move chrome-trace types into a new perfetto-trace crate The Trace and TraceEvent types from support-bundle-collection are now in a standalone perfetto-trace crate, so that other crates can emit traces without depending on the full support bundle machinery. The old support_bundle_collection::perfetto path still works via a re-export. The new crate also gains a TraceSpan recording type, a timed() future bracketing helper, and an assemble() function that packs spans into the minimum number of tid lanes (greedy interval packing), so the lane count in the viewer reflects the maximum observed concurrency. --- Cargo.lock | 11 + Cargo.toml | 3 + perfetto-trace/Cargo.toml | 14 ++ perfetto-trace/src/lib.rs | 254 ++++++++++++++++++++++ support-bundle-collection/Cargo.toml | 1 + support-bundle-collection/src/lib.rs | 2 +- support-bundle-collection/src/perfetto.rs | 51 ----- 7 files changed, 284 insertions(+), 52 deletions(-) create mode 100644 perfetto-trace/Cargo.toml create mode 100644 perfetto-trace/src/lib.rs delete mode 100644 support-bundle-collection/src/perfetto.rs diff --git a/Cargo.lock b/Cargo.lock index fe54ccac6f1..29e224cb1ce 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -11049,6 +11049,16 @@ version = "2.3.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "9b4f627cb1b25917193a259e49bdad08f671f8d9708acfd5fe0a8c1455d87220" +[[package]] +name = "perfetto-trace" +version = "0.1.0" +dependencies = [ + "chrono", + "omicron-workspace-hack", + "serde", + "serde_json", +] + [[package]] name = "pest" version = "2.8.6" @@ -15147,6 +15157,7 @@ dependencies = [ "omicron-uuid-kinds", "omicron-workspace-hack", "parallel-task-set", + "perfetto-trace", "pq-sys", "serde", "serde_json", diff --git a/Cargo.toml b/Cargo.toml index fc16e0bc2d9..82126e0da9f 100644 --- a/Cargo.toml +++ b/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. diff --git a/perfetto-trace/Cargo.toml b/perfetto-trace/Cargo.toml new file mode 100644 index 00000000000..f63a5b3102a --- /dev/null +++ b/perfetto-trace/Cargo.toml @@ -0,0 +1,14 @@ +[package] +name = "perfetto-trace" +version = "0.1.0" +edition.workspace = true +license = "MPL-2.0" + +[dependencies] +chrono.workspace = true +serde.workspace = true +serde_json.workspace = true +omicron-workspace-hack.workspace = true + +[lints] +workspace = true diff --git a/perfetto-trace/src/lib.rs b/perfetto-trace/src/lib.rs new file mode 100644 index 00000000000..917af145992 --- /dev/null +++ b/perfetto-trace/src/lib.rs @@ -0,0 +1,254 @@ +// This Source Code Form is subject to the terms of the Mozilla Public +// License, v. 2.0. If a copy of the MPL was not distributed with this +// file, You can obtain one at https://mozilla.org/MPL/2.0/. + +//! Chrome Trace Event format support for visualizing operation timing +//! +//! Traces produced with this crate can be loaded into the Perfetto trace +//! viewer () or `chrome://tracing`. + +use chrono::DateTime; +use chrono::Utc; +use serde::Deserialize; +use serde::Serialize; + +/// Represents a Perfetto Trace Event format JSON file for visualization. +/// +/// This format is used by the Perfetto trace viewer () +/// to visualize timing information for operations. +#[derive(Clone, Debug, PartialEq, Serialize, Deserialize)] +pub struct Trace { + #[serde(rename = "traceEvents")] + pub trace_events: Vec, + /// Display unit for time values in the UI (e.g., "ms" for milliseconds) + #[serde(rename = "displayTimeUnit")] + pub display_time_unit: String, +} + +/// A single event in the Perfetto Trace Event format. +/// +/// This represents a complete event (duration event) showing when an operation +/// started and how long it took. +#[derive(Clone, Debug, PartialEq, Serialize, Deserialize)] +pub struct TraceEvent { + /// Human-readable name of the event + pub name: String, + /// Category name (abbreviated as "cat" in Perfetto format). + /// Used to group related events together in the trace viewer. + pub cat: String, + /// Phase type (abbreviated as "ph" in Perfetto format). + /// "X" means a "Complete" event with both timestamp and duration. + pub ph: String, + /// Timestamp in microseconds (abbreviated as "ts" in Perfetto format). + /// Represents when the event started, as microseconds since the epoch. + pub ts: i64, + /// Duration in microseconds (abbreviated as "dur" in Perfetto format). + /// How long the event took to complete. + pub dur: i64, + /// Process ID. Used to separate events into different process lanes + /// in the trace viewer. + pub pid: u32, + /// Thread ID. Used to separate events into different thread lanes + /// within a process in the trace viewer. + pub tid: usize, + /// Arbitrary key-value pairs with additional event metadata + pub args: serde_json::Value, +} + +/// A completed timed operation, recorded with wall-clock timestamps. +/// +/// Spans are collected while work runs and later converted into a [`Trace`] +/// with [`assemble`]. +#[derive(Clone, Debug, PartialEq, Serialize, Deserialize)] +pub struct TraceSpan { + /// Name identifying the specific operation (e.g., a target URL) + pub name: String, + /// The kind of operation, used for grouping and filtering + pub category: String, + pub start: DateTime, + pub end: DateTime, + /// Arbitrary key-value pairs with additional metadata + pub args: serde_json::Value, +} + +impl TraceSpan { + /// Creates a span lasting from `start` until now. + pub fn since( + name: impl Into, + category: impl Into, + start: DateTime, + ) -> Self { + TraceSpan { + name: name.into(), + category: category.into(), + start, + end: Utc::now(), + args: serde_json::Value::Null, + } + } +} + +/// Runs `fut` to completion, returning its output along with a [`TraceSpan`] +/// covering its execution. +pub async fn timed( + name: impl Into, + category: impl Into, + fut: impl Future, +) -> (TraceSpan, T) { + let start = Utc::now(); + let output = fut.await; + (TraceSpan::since(name, category, start), output) +} + +/// Assembles spans into a [`Trace`] in the Chrome Trace Event format. +/// +/// Spans are packed into the minimum number of `tid` lanes: each span is +/// assigned the lowest-numbered lane that is free at its start time. The +/// trace format renders overlapping events in a single lane poorly, so +/// concurrent spans must land in separate lanes; packing (rather than giving +/// every event its own lane) keeps the lane count equal to the maximum +/// observed concurrency. Spans are sorted by start time with ties broken by +/// later end time, so a span that fully contains others (e.g., a phase +/// containing the operations it ran) is placed in a lower lane than its +/// contents. +pub fn assemble(mut spans: Vec) -> Trace { + spans.sort_by(|a, b| a.start.cmp(&b.start).then_with(|| b.end.cmp(&a.end))); + + // The end time of the last span assigned to each lane. + let mut lane_ends: Vec> = Vec::new(); + let trace_events = spans + .into_iter() + .map(|span| { + // Guard against clock adjustments making a span end before it + // starts. + let end = span.end.max(span.start); + let tid = match lane_ends + .iter() + .position(|lane_end| *lane_end <= span.start) + { + Some(lane) => { + lane_ends[lane] = end; + lane + } + None => { + lane_ends.push(end); + lane_ends.len() - 1 + } + }; + TraceEvent { + name: span.name, + cat: span.category, + ph: "X".to_string(), + ts: span.start.timestamp_micros(), + dur: (end - span.start).num_microseconds().unwrap_or(0), + pid: 1, + tid, + args: span.args, + } + }) + .collect(); + + Trace { trace_events, display_time_unit: "ms".to_string() } +} + +#[cfg(test)] +mod test { + use super::*; + use chrono::TimeZone; + + fn span(name: &str, start_us: i64, end_us: i64) -> TraceSpan { + TraceSpan { + name: name.to_string(), + category: "test".to_string(), + start: Utc.timestamp_micros(start_us).unwrap(), + end: Utc.timestamp_micros(end_us).unwrap(), + args: serde_json::Value::Null, + } + } + + fn lanes_by_name(trace: &Trace) -> Vec<(String, usize)> { + trace.trace_events.iter().map(|e| (e.name.clone(), e.tid)).collect() + } + + #[test] + fn test_overlapping_spans_get_distinct_lanes() { + let trace = assemble(vec![ + span("a", 0, 100), + span("b", 50, 150), + span("c", 75, 200), + ]); + assert_eq!( + lanes_by_name(&trace), + vec![ + ("a".to_string(), 0), + ("b".to_string(), 1), + ("c".to_string(), 2), + ] + ); + } + + #[test] + fn test_lane_reuse_after_span_ends() { + let trace = assemble(vec![ + span("a", 0, 100), + span("b", 50, 150), + span("c", 100, 200), + ]); + // "c" starts exactly when "a" ends, so it reuses lane 0. + assert_eq!( + lanes_by_name(&trace), + vec![ + ("a".to_string(), 0), + ("b".to_string(), 1), + ("c".to_string(), 0), + ] + ); + } + + #[test] + fn test_containing_span_gets_lower_lane() { + // A "phase" span fully contains the operations it ran, including one + // starting at the same instant. The tie is broken by later end time, + // so the phase lands in lane 0. + let trace = assemble(vec![ + span("op1", 0, 50), + span("phase", 0, 200), + span("op2", 50, 150), + ]); + assert_eq!( + lanes_by_name(&trace), + vec![ + ("phase".to_string(), 0), + ("op1".to_string(), 1), + ("op2".to_string(), 1), + ] + ); + } + + #[test] + fn test_event_field_mapping() { + let mut trace = assemble(vec![span("a", 25, 100)]); + let event = trace.trace_events.pop().unwrap(); + assert_eq!(event.ts, 25); + assert_eq!(event.dur, 75); + assert_eq!(event.ph, "X"); + assert_eq!(event.cat, "test"); + assert_eq!(event.pid, 1); + + // A span ending before it starts (clock adjustment) clamps to zero + // duration rather than going negative. + let mut trace = assemble(vec![span("b", 100, 25)]); + assert_eq!(trace.trace_events.pop().unwrap().dur, 0); + } + + #[test] + fn test_serialized_key_names() { + let trace = assemble(vec![span("a", 0, 100)]); + let json = serde_json::to_value(&trace).unwrap(); + assert!(json.get("traceEvents").is_some()); + assert_eq!( + json.get("displayTimeUnit").unwrap(), + &serde_json::Value::String("ms".to_string()) + ); + } +} diff --git a/support-bundle-collection/Cargo.toml b/support-bundle-collection/Cargo.toml index f26f5f6e295..0a80480ca39 100644 --- a/support-bundle-collection/Cargo.toml +++ b/support-bundle-collection/Cargo.toml @@ -30,6 +30,7 @@ nexus-types.workspace = true omicron-common.workspace = true omicron-uuid-kinds.workspace = true parallel-task-set.workspace = true +perfetto-trace.workspace = true # See omicron-rpaths for more about the "pq-sys" dependency. pq-sys = "*" serde.workspace = true diff --git a/support-bundle-collection/src/lib.rs b/support-bundle-collection/src/lib.rs index fd9c6dc6094..bb14bbc8791 100644 --- a/support-bundle-collection/src/lib.rs +++ b/support-bundle-collection/src/lib.rs @@ -14,7 +14,7 @@ mod cache; pub mod collection; -pub mod perfetto; +pub use perfetto_trace as perfetto; mod step; mod steps; pub mod zip; diff --git a/support-bundle-collection/src/perfetto.rs b/support-bundle-collection/src/perfetto.rs deleted file mode 100644 index 8653b7b907b..00000000000 --- a/support-bundle-collection/src/perfetto.rs +++ /dev/null @@ -1,51 +0,0 @@ -// This Source Code Form is subject to the terms of the Mozilla Public -// License, v. 2.0. If a copy of the MPL was not distributed with this -// file, You can obtain one at https://mozilla.org/MPL/2.0/. - -//! Perfetto Trace Event format support for visualizing support bundle collection - -use serde::Deserialize; -use serde::Serialize; - -/// Represents a Perfetto Trace Event format JSON file for visualization. -/// -/// This format is used by the Perfetto trace viewer () -/// to visualize timing information for operations. -#[derive(Serialize, Deserialize)] -pub struct Trace { - #[serde(rename = "traceEvents")] - pub trace_events: Vec, - /// Display unit for time values in the UI (e.g., "ms" for milliseconds) - #[serde(rename = "displayTimeUnit")] - pub display_time_unit: String, -} - -/// A single event in the Perfetto Trace Event format. -/// -/// This represents a complete event (duration event) showing when an operation -/// started and how long it took. -#[derive(Serialize, Deserialize)] -pub struct TraceEvent { - /// Human-readable name of the event - pub name: String, - /// Category name (abbreviated as "cat" in Perfetto format). - /// Used to group related events together in the trace viewer. - pub cat: String, - /// Phase type (abbreviated as "ph" in Perfetto format). - /// "X" means a "Complete" event with both timestamp and duration. - pub ph: String, - /// Timestamp in microseconds (abbreviated as "ts" in Perfetto format). - /// Represents when the event started, as microseconds since the epoch. - pub ts: i64, - /// Duration in microseconds (abbreviated as "dur" in Perfetto format). - /// How long the event took to complete. - pub dur: i64, - /// Process ID. Used to separate events into different process lanes - /// in the trace viewer. - pub pid: u32, - /// Thread ID. Used to separate events into different thread lanes - /// within a process in the trace viewer. - pub tid: usize, - /// Arbitrary key-value pairs with additional event metadata - pub args: serde_json::Value, -} From 68029e6810a36cb8fdd118aea1ef2912090ef6ec Mon Sep 17 00:00:00 2001 From: Sean Klein Date: Thu, 6 Aug 2026 15:44:35 -0700 Subject: [PATCH 2/3] Record timing spans during inventory collection The Collector now records a TraceSpan for each collection phase, each request made within the concurrent phases (sled agents, timesync, keepers, DNS generations), each MGS client, and each SP queried through MGS. The per-SP work moves into a new collect_one_sp helper so it can be bracketed as a unit; its behavior is unchanged. collect_all returns the spans alongside the Collection. The inventory background task assembles them into a Chrome Trace Event format trace and reports it in its activation status via the new shared InventoryCollectionStatus type, so the last collection's timing can be retrieved from the running Nexus and loaded into ui.perfetto.dev. The trace is not persisted anywhere: a failed activation, or asking a Nexus that has not collected since it started, yields no trace. --- Cargo.lock | 3 + nexus/Cargo.toml | 1 + nexus/inventory/Cargo.toml | 1 + nexus/inventory/src/collector.rs | 584 ++++++++++-------- .../background/tasks/inventory_collection.rs | 37 +- nexus/types/Cargo.toml | 1 + nexus/types/src/internal_api/background.rs | 17 + 7 files changed, 389 insertions(+), 255 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 29e224cb1ce..4e48f2cb66f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -7646,6 +7646,7 @@ dependencies = [ "omicron-uuid-kinds", "omicron-workspace-hack", "parallel-task-set", + "perfetto-trace", "regex", "reqwest 0.13.2", "serde_json", @@ -8268,6 +8269,7 @@ dependencies = [ "oxnet", "oxql-types", "parse-display", + "perfetto-trace", "proptest", "regex", "schemars 0.8.22", @@ -9243,6 +9245,7 @@ dependencies = [ "parse-display", "paste", "pem", + "perfetto-trace", "petgraph 0.8.3", "pq-sys", "pretty_assertions", diff --git a/nexus/Cargo.toml b/nexus/Cargo.toml index 710224338af..01ca6a67787 100644 --- a/nexus/Cargo.toml +++ b/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 diff --git a/nexus/inventory/Cargo.toml b/nexus/inventory/Cargo.toml index 414a184ff89..b79bb985c9b 100644 --- a/nexus/inventory/Cargo.toml +++ b/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 diff --git a/nexus/inventory/src/collector.rs b/nexus/inventory/src/collector.rs index 12c2b97bcee..ac6981b916f 100644 --- a/nexus/inventory/src/collector.rs +++ b/nexus/inventory/src/collector.rs @@ -9,11 +9,13 @@ use crate::builder::CollectionBuilder; use crate::builder::InventoryError; use anyhow::Context; use anyhow::anyhow; +use chrono::Utc; use clickhouse_admin_keeper_client::ClientInfo as _; use clickhouse_admin_types::keeper::ClickhouseKeeperClusterMembership; use gateway_client::types::GetCfpaParams; use gateway_client::types::RotCfpaSlot; use gateway_messages::SpComponent; +use gateway_types::component::SpIdentifier; use itertools::Itertools; use nexus_types::inventory::CabooseWhich; use nexus_types::inventory::Collection; @@ -27,6 +29,8 @@ use omicron_common::address::NTP_ADMIN_PORT; use omicron_common::disk::M2Slot; use omicron_uuid_kinds::OmicronZoneUuid; use parallel_task_set::ParallelTaskSet; +use perfetto_trace::TraceSpan; +use perfetto_trace::timed; use sled_agent_types::inventory::Inventory; use sled_agent_types::inventory::OmicronZoneType; use sled_agent_types::inventory::ZoneKind; @@ -52,6 +56,7 @@ pub struct Collector<'a> { cockroach_admin_client: &'a CockroachClusterAdminClient, sled_agent_lister: &'a (dyn SledAgentEnumerator + Send + Sync), in_progress: CollectionBuilder, + spans: Vec, } impl<'a> Collector<'a> { @@ -70,6 +75,7 @@ impl<'a> Collector<'a> { cockroach_admin_client, sled_agent_lister, in_progress: CollectionBuilder::new(creator), + spans: Vec::new(), } } @@ -80,7 +86,13 @@ impl<'a> Collector<'a> { /// components. This can take a while and produce any number of errors. /// Such errors generally don't cause this function to fail. Rather, the /// returned `Collection` keeps track of these errors. - pub async fn collect_all(mut self) -> Result { + /// + /// Also returns a set of timing spans covering each phase of the + /// collection and each request made within the concurrent phases, + /// suitable for assembling into a trace with `perfetto_trace::assemble`. + pub async fn collect_all( + mut self, + ) -> Result<(Collection, Vec), anyhow::Error> { // Most of the phases below fan requests out to their targets with // bounded concurrency (MAX_CONCURRENT_INVENTORY_REQUESTS) and then // merge the results into the in-progress collection on this task. @@ -95,26 +107,53 @@ impl<'a> Collector<'a> { debug!(&self.log, "begin collection"); + let start = Utc::now(); self.collect_all_mgs().await; + self.spans.push(TraceSpan::since("mgs", "phase", start)); + + let start = Utc::now(); self.collect_all_sled_agents().await; + self.spans.push(TraceSpan::since("sled_agents", "phase", start)); + + let start = Utc::now(); self.collect_all_keepers().await; + self.spans.push(TraceSpan::since("keepers", "phase", start)); + + let start = Utc::now(); self.collect_all_cockroach().await; + self.spans.push(TraceSpan::since("cockroach", "phase", start)); // The following must be called after "collect_all_sled_agents", // or they'll see an empty set of services. + let start = Utc::now(); self.collect_all_timesync().await; + self.spans.push(TraceSpan::since("timesync", "phase", start)); + + let start = Utc::now(); self.collect_all_dns_generations().await; + self.spans.push(TraceSpan::since("dns_generations", "phase", start)); debug!(&self.log, "finished collection"); - Ok(self.in_progress.build()) + Ok((self.in_progress.build(), self.spans)) } /// Collect inventory from all MGS instances async fn collect_all_mgs(&mut self) { for client in &self.mgs_clients { - Self::collect_one_mgs(client, &self.log, &mut self.in_progress) - .await; + let start = Utc::now(); + Self::collect_one_mgs( + client, + &self.log, + &mut self.in_progress, + &mut self.spans, + ) + .await; + self.spans.push(TraceSpan::since( + client.baseurl(), + "mgs_client", + start, + )); } } @@ -122,6 +161,7 @@ impl<'a> Collector<'a> { client: &gateway_client::Client, log: &Logger, in_progress: &mut CollectionBuilder, + spans: &mut Vec, ) { debug!(log, "begin collection from MGS"; "mgs_url" => client.baseurl() @@ -163,277 +203,280 @@ impl<'a> Collector<'a> { // For each SP that ignition reports up, fetch the state and caboose // information. for sp in sps { - // First, fetch the state of the SP. If that fails, report the - // error but continue. - let result = - client.sp_get(&sp.typ, sp.slot).await.with_context(|| { - format!( - "MGS {:?}: fetching state of SP {:?}", - client.baseurl(), - sp - ) - }); - let sp_state = match result { - Err(error) => { - in_progress.found_error(InventoryError::from(error)); - continue; - } - Ok(response) => response.into_inner(), - }; + let start = Utc::now(); + let name = format!("sp {:?} {}", sp.typ, sp.slot); + Self::collect_one_sp(client, log, in_progress, sp).await; + spans.push(TraceSpan::since(name, "sp", start)); + } + } - // Record the state that we found. - let Some(baseboard_id) = in_progress.found_sp_state( - client.baseurl(), - sp.typ, - sp.slot, - sp_state, - ) else { - // We failed to parse this SP for some reason. The error was - // reported already. Move on. - continue; - }; + /// Collect inventory reported by one MGS instance for one SP + async fn collect_one_sp( + client: &gateway_client::Client, + log: &Logger, + in_progress: &mut CollectionBuilder, + sp: SpIdentifier, + ) { + // First, fetch the state of the SP. If that fails, report the + // error but continue. + let result = client.sp_get(&sp.typ, sp.slot).await.with_context(|| { + format!("MGS {:?}: fetching state of SP {:?}", client.baseurl(), sp) + }); + let sp_state = match result { + Err(error) => { + in_progress.found_error(InventoryError::from(error)); + return; + } + Ok(response) => response.into_inner(), + }; - // For sled SPs, collect the currently-active phase 1 slot and the - // hash of the contents of both slots, if they haven't been - // collected already. Generally, we'd only get here for the first - // MGS client. Assuming that one succeeds, the other(s) will skip - // this loop. - if matches!(sp.typ, SpType::Sled) { - if !in_progress - .found_host_phase_1_active_slot_already(&baseboard_id) - { - let result = client - .sp_component_active_slot_get( - &sp.typ, - sp.slot, - SpComponent::HOST_CPU_BOOT_FLASH.const_as_str(), + // Record the state that we found. + let Some(baseboard_id) = in_progress.found_sp_state( + client.baseurl(), + sp.typ, + sp.slot, + sp_state, + ) else { + // We failed to parse this SP for some reason. The error was + // reported already. Move on. + return; + }; + + // For sled SPs, collect the currently-active phase 1 slot and the + // hash of the contents of both slots, if they haven't been + // collected already. Generally, we'd only get here for the first + // MGS client. Assuming that one succeeds, the other(s) will skip + // this loop. + if matches!(sp.typ, SpType::Sled) { + if !in_progress + .found_host_phase_1_active_slot_already(&baseboard_id) + { + let result = client + .sp_component_active_slot_get( + &sp.typ, + sp.slot, + SpComponent::HOST_CPU_BOOT_FLASH.const_as_str(), + ) + .await + .with_context(|| { + format!( + "MGS {:?}: SP {sp:?}: phase 1 active slot", + client.baseurl(), ) - .await - .with_context(|| { - format!( - "MGS {:?}: SP {sp:?}: phase 1 active slot", - client.baseurl(), - ) - }) - .and_then(|response| { - M2Slot::from_mgs_firmware_slot(response.slot) - .ok_or_else(|| { - anyhow!( - "MGS {:?}: SP {sp:?}: \ + }) + .and_then(|response| { + M2Slot::from_mgs_firmware_slot(response.slot) + .ok_or_else(|| { + anyhow!( + "MGS {:?}: SP {sp:?}: \ invalid host phase 1 slot {}", - client.baseurl(), - response.slot - ) - }) - }); - match result { - Ok(phase_1_slot) => { - if let Err(error) = in_progress - .found_host_phase_1_active_slot( - &baseboard_id, client.baseurl(), - phase_1_slot, + response.slot ) - { - error!( - log, - "error reporting host phase 1 active slot: \ + }) + }); + match result { + Ok(phase_1_slot) => { + if let Err(error) = in_progress + .found_host_phase_1_active_slot( + &baseboard_id, + client.baseurl(), + phase_1_slot, + ) + { + error!( + log, + "error reporting host phase 1 active slot: \ {baseboard_id:?} {phase_1_slot:?} \ {:?}: {error:#}", - client.baseurl(), - ); - } - } - Err(err) => { - in_progress.found_error(InventoryError::from(err)); - } - } - } - - for slot in M2Slot::iter() { - const PHASE1_HASH_TIMEOUT: Duration = - Duration::from_secs(30); - - if in_progress.found_host_phase_1_flash_hash_already( - &baseboard_id, - slot, - ) { - continue; - } - - let phase1_slot = match slot { - M2Slot::A => 0, - M2Slot::B => 1, - }; - - let result = client - .host_phase_1_flash_hash_calculate_with_timeout( - sp.typ, - sp.slot, - phase1_slot, - PHASE1_HASH_TIMEOUT, - ) - .await - .with_context(|| { - format!( - "MGS {:?}: SP {sp:?}: phase 1 slot {slot:?}", client.baseurl(), - ) - }); - let hash = match result { - Err(error) => { - in_progress - .found_error(InventoryError::from(error)); - continue; + ); } - Ok(hash) => hash, - }; - if let Err(error) = in_progress - .found_host_phase_1_flash_hash( - &baseboard_id, - slot, - client.baseurl(), - ArtifactHash(hash), - ) - { - error!( - log, - "error reporting host phase 1 flash hash: \ - {baseboard_id:?} {slot:?} {:?}: {error:#}", - client.baseurl(), - ); + } + Err(err) => { + in_progress.found_error(InventoryError::from(err)); } } } - // For each kind of caboose that we care about, if it hasn't been - // fetched already, fetch it and record it. Generally, we'd only - // get here for the first MGS client. Assuming that one succeeds, - // the other(s) will skip this loop. - for which in CabooseWhich::iter() { - if in_progress.found_caboose_already(&baseboard_id, which) { + for slot in M2Slot::iter() { + const PHASE1_HASH_TIMEOUT: Duration = Duration::from_secs(30); + + if in_progress + .found_host_phase_1_flash_hash_already(&baseboard_id, slot) + { continue; } - let (component, slot) = match which { - CabooseWhich::SpSlot0 => ("sp", 0), - CabooseWhich::SpSlot1 => ("sp", 1), - CabooseWhich::RotSlotA => ("rot", 0), - CabooseWhich::RotSlotB => ("rot", 1), - CabooseWhich::Stage0 => ("stage0", 0), - CabooseWhich::Stage0Next => ("stage0", 1), + let phase1_slot = match slot { + M2Slot::A => 0, + M2Slot::B => 1, }; let result = client - .sp_component_caboose_get(&sp.typ, sp.slot, component, slot) + .host_phase_1_flash_hash_calculate_with_timeout( + sp.typ, + sp.slot, + phase1_slot, + PHASE1_HASH_TIMEOUT, + ) .await .with_context(|| { format!( - "MGS {:?}: SP {:?}: caboose {:?}", + "MGS {:?}: SP {sp:?}: phase 1 slot {slot:?}", client.baseurl(), - sp, - which ) }); - let caboose = match result { + let hash = match result { Err(error) => { in_progress.found_error(InventoryError::from(error)); continue; } - Ok(response) => response.into_inner(), + Ok(hash) => hash, }; - if let Err(error) = in_progress.found_caboose( + if let Err(error) = in_progress.found_host_phase_1_flash_hash( &baseboard_id, - which, + slot, client.baseurl(), - caboose, + ArtifactHash(hash), ) { error!( log, - "error reporting caboose: {:?} {:?} {:?}: {:#}", - baseboard_id, - which, + "error reporting host phase 1 flash hash: \ + {baseboard_id:?} {slot:?} {:?}: {error:#}", client.baseurl(), - error ); } } + } + + // For each kind of caboose that we care about, if it hasn't been + // fetched already, fetch it and record it. Generally, we'd only + // get here for the first MGS client. Assuming that one succeeds, + // the other(s) will skip this loop. + for which in CabooseWhich::iter() { + if in_progress.found_caboose_already(&baseboard_id, which) { + continue; + } - // For each kind of RoT page that we care about, if it hasn't been - // fetched already, fetch it and record it. Generally, we'd only - // get here for the first MGS client. Assuming that one succeeds, - // the other(s) will skip this loop. - for which in RotPageWhich::iter() { - if in_progress.found_rot_page_already(&baseboard_id, which) { - continue; - } + let (component, slot) = match which { + CabooseWhich::SpSlot0 => ("sp", 0), + CabooseWhich::SpSlot1 => ("sp", 1), + CabooseWhich::RotSlotA => ("rot", 0), + CabooseWhich::RotSlotB => ("rot", 1), + CabooseWhich::Stage0 => ("stage0", 0), + CabooseWhich::Stage0Next => ("stage0", 1), + }; - let component = SpComponent::ROT.const_as_str(); - - let result = match which { - RotPageWhich::Cmpa => client - .sp_rot_cmpa_get(&sp.typ, sp.slot, component) - .await - .map(|response| response.into_inner().base64_data), - RotPageWhich::CfpaActive => client - .sp_rot_cfpa_get( - &sp.typ, - sp.slot, - component, - &GetCfpaParams { slot: RotCfpaSlot::Active }, - ) - .await - .map(|response| response.into_inner().base64_data), - RotPageWhich::CfpaInactive => client - .sp_rot_cfpa_get( - &sp.typ, - sp.slot, - component, - &GetCfpaParams { slot: RotCfpaSlot::Inactive }, - ) - .await - .map(|response| response.into_inner().base64_data), - RotPageWhich::CfpaScratch => client - .sp_rot_cfpa_get( - &sp.typ, - sp.slot, - component, - &GetCfpaParams { slot: RotCfpaSlot::Scratch }, - ) - .await - .map(|response| response.into_inner().base64_data), - } + let result = client + .sp_component_caboose_get(&sp.typ, sp.slot, component, slot) + .await .with_context(|| { format!( - "MGS {:?}: SP {:?}: rot page {:?}", + "MGS {:?}: SP {:?}: caboose {:?}", client.baseurl(), sp, which ) }); - - let page = match result { - Err(error) => { - in_progress.found_error(InventoryError::from(error)); - continue; - } - Ok(data_base64) => RotPage { data_base64 }, - }; - if let Err(error) = in_progress.found_rot_page( - &baseboard_id, + let caboose = match result { + Err(error) => { + in_progress.found_error(InventoryError::from(error)); + continue; + } + Ok(response) => response.into_inner(), + }; + if let Err(error) = in_progress.found_caboose( + &baseboard_id, + which, + client.baseurl(), + caboose, + ) { + error!( + log, + "error reporting caboose: {:?} {:?} {:?}: {:#}", + baseboard_id, which, client.baseurl(), - page, - ) { - error!( - log, - "error reporting rot page: {:?} {:?} {:?}: {:#}", - baseboard_id, - which, - client.baseurl(), - error - ); + error + ); + } + } + + // For each kind of RoT page that we care about, if it hasn't been + // fetched already, fetch it and record it. Generally, we'd only + // get here for the first MGS client. Assuming that one succeeds, + // the other(s) will skip this loop. + for which in RotPageWhich::iter() { + if in_progress.found_rot_page_already(&baseboard_id, which) { + continue; + } + + let component = SpComponent::ROT.const_as_str(); + + let result = match which { + RotPageWhich::Cmpa => client + .sp_rot_cmpa_get(&sp.typ, sp.slot, component) + .await + .map(|response| response.into_inner().base64_data), + RotPageWhich::CfpaActive => client + .sp_rot_cfpa_get( + &sp.typ, + sp.slot, + component, + &GetCfpaParams { slot: RotCfpaSlot::Active }, + ) + .await + .map(|response| response.into_inner().base64_data), + RotPageWhich::CfpaInactive => client + .sp_rot_cfpa_get( + &sp.typ, + sp.slot, + component, + &GetCfpaParams { slot: RotCfpaSlot::Inactive }, + ) + .await + .map(|response| response.into_inner().base64_data), + RotPageWhich::CfpaScratch => client + .sp_rot_cfpa_get( + &sp.typ, + sp.slot, + component, + &GetCfpaParams { slot: RotCfpaSlot::Scratch }, + ) + .await + .map(|response| response.into_inner().base64_data), + } + .with_context(|| { + format!( + "MGS {:?}: SP {:?}: rot page {:?}", + client.baseurl(), + sp, + which + ) + }); + + let page = match result { + Err(error) => { + in_progress.found_error(InventoryError::from(error)); + continue; } + Ok(data_base64) => RotPage { data_base64 }, + }; + if let Err(error) = in_progress.found_rot_page( + &baseboard_id, + which, + client.baseurl(), + page, + ) { + error!( + log, + "error reporting rot page: {:?} {:?} {:?}: {:#}", + baseboard_id, + which, + client.baseurl(), + error + ); } } } @@ -455,8 +498,13 @@ impl<'a> Collector<'a> { for (idx, url) in urls.into_iter().enumerate() { let log = self.log.new(o!("SledAgent" => url.clone())); let task = async move { - let result = collect_one_sled_agent(&url, log).await; - (idx, url, result) + let (span, result) = timed( + url.clone(), + "sled_agent", + collect_one_sled_agent(&url, log), + ) + .await; + (idx, url, result, span) }; if let Some(result) = tasks.spawn(task).await { results.push(result); @@ -467,8 +515,9 @@ impl<'a> Collector<'a> { // Merge results in the order we enumerated the sleds, so that the // collection's contents (in particular the order of its errors) do // not depend on request completion order. - results.sort_by_key(|(idx, _, _)| *idx); - for (_, url, result) in results { + results.sort_by_key(|(idx, _, _, _)| *idx); + for (_, url, result, span) in results { + self.spans.push(span); match result { Err(error) => self.in_progress.found_error(error), Ok(inventory) => { @@ -521,8 +570,13 @@ impl<'a> Collector<'a> { { let log = self.log.clone(); let task = async move { - let result = collect_one_timesync(&log, zone_id, &client).await; - (idx, zone_id, result) + let (span, result) = timed( + zone_id.to_string(), + "timesync", + collect_one_timesync(&log, zone_id, &client), + ) + .await; + (idx, zone_id, result, span) }; if let Some(result) = tasks.spawn(task).await { results.push(result); @@ -530,8 +584,9 @@ impl<'a> Collector<'a> { } results.extend(tasks.join_remaining().await); - results.sort_by_key(|(idx, _, _)| *idx); - for (_, zone_id, result) in results { + results.sort_by_key(|(idx, _, _, _)| *idx); + for (_, zone_id, result, span) in results { + self.spans.push(span); match result { Err(error) => self.in_progress.found_error(error), Ok(timesync) => { @@ -566,8 +621,13 @@ impl<'a> Collector<'a> { let client = client.clone(); let log = self.log.clone(); let task = async move { - let result = collect_one_keeper(&client, &log).await; - (idx, result) + let (span, result) = timed( + client.baseurl().to_string(), + "keeper", + collect_one_keeper(&client, &log), + ) + .await; + (idx, result, span) }; if let Some(result) = tasks.spawn(task).await { results.push(result); @@ -575,8 +635,9 @@ impl<'a> Collector<'a> { } results.extend(tasks.join_remaining().await); - results.sort_by_key(|(idx, _)| *idx); - for (_, result) in results { + results.sort_by_key(|(idx, _, _)| *idx); + for (_, result, span) in results { + self.spans.push(span); match result { Err(error) => self.in_progress.found_error(error), Ok(membership) => self @@ -650,9 +711,13 @@ impl<'a> Collector<'a> { { let log = self.log.clone(); let task = async move { - let result = - collect_one_dns_generation(&log, zone_id, &client).await; - (idx, zone_id, result) + let (span, result) = timed( + zone_id.to_string(), + "dns_generation", + collect_one_dns_generation(&log, zone_id, &client), + ) + .await; + (idx, zone_id, result, span) }; if let Some(result) = tasks.spawn(task).await { results.push(result); @@ -660,8 +725,9 @@ impl<'a> Collector<'a> { } results.extend(tasks.join_remaining().await); - results.sort_by_key(|(idx, _, _)| *idx); - for (_, zone_id, result) in results { + results.sort_by_key(|(idx, _, _, _)| *idx); + for (_, zone_id, result, span) in results { + self.spans.push(span); let result = result.and_then(|generation_status| { self.in_progress .found_internal_dns_generation_status(generation_status) @@ -1191,7 +1257,7 @@ mod test { &sled_enum, log.clone(), ); - let collection = collector + let (collection, spans) = collector .collect_all() .await .expect("failed to carry out collection"); @@ -1202,6 +1268,36 @@ mod test { ); assert_eq!(collection.collector, "test-suite"); + // The timing spans should cover every phase, in the order the phases + // run, without overlap. + let phases: Vec<_> = + spans.iter().filter(|s| s.category == "phase").collect(); + assert_eq!( + phases.iter().map(|s| s.name.as_str()).collect::>(), + vec![ + "mgs", + "sled_agents", + "keepers", + "cockroach", + "timesync", + "dns_generations" + ] + ); + for pair in phases.windows(2) { + assert!(pair[1].start >= pair[0].end); + } + for span in &spans { + assert!(span.end >= span.start); + } + + // One span per collected target: two sled agents, one MGS client, + // and at least one SP behind it. + let count = + |cat: &str| spans.iter().filter(|s| s.category == cat).count(); + assert_eq!(count("sled_agent"), 2); + assert_eq!(count("mgs_client"), 1); + assert!(count("sp") >= 1); + let s = dump_collection(&collection); expectorate::assert_contents("tests/output/collector_basic.txt", &s); @@ -1271,7 +1367,7 @@ mod test { &sled_enum, log.clone(), ); - let collection = collector + let (collection, _spans) = collector .collect_all() .await .expect("failed to carry out collection"); @@ -1321,7 +1417,7 @@ mod test { &sled_enum, log.clone(), ); - let collection = collector + let (collection, _spans) = collector .collect_all() .await .expect("failed to carry out collection"); @@ -1378,7 +1474,7 @@ mod test { &sled_enum, log.clone(), ); - let collection = collector + let (collection, _spans) = collector .collect_all() .await .expect("failed to carry out collection"); diff --git a/nexus/src/app/background/tasks/inventory_collection.rs b/nexus/src/app/background/tasks/inventory_collection.rs index c6f8682996e..1784686b0c9 100644 --- a/nexus/src/app/background/tasks/inventory_collection.rs +++ b/nexus/src/app/background/tasks/inventory_collection.rs @@ -15,9 +15,11 @@ use nexus_db_queries::db::DataStore; use nexus_inventory::InventoryError; use nexus_networking::GatewayClient; use nexus_types::deployment::SledFilter; +use nexus_types::internal_api::background::InventoryCollectionStatus; use nexus_types::inventory::Collection; use omicron_cockroach_metrics::CockroachClusterAdminClient; use omicron_uuid_kinds::CollectionUuid; +use perfetto_trace::TraceSpan; use serde_json::json; use slog::{debug, o, warn}; use std::net::SocketAddr; @@ -93,18 +95,21 @@ impl BackgroundTask for InventoryCollector { "error" => message.clone()); json!({ "error": message }) } - Ok(collection) => { + Ok((collection, spans)) => { debug!(opctx.log, "inventory collection complete"; "collection_id" => collection.id.to_string(), "time_started" => collection.time_started.to_string(), ); - let json = json!({ - "collection_id": collection.id.to_string(), - "time_started": collection.time_started.to_string(), - "time_done": collection.time_done.to_string() - }); + let status = InventoryCollectionStatus { + collection_id: collection.id, + time_started: collection.time_started, + time_done: collection.time_done, + trace: Some(perfetto_trace::assemble(spans)), + }; self.tx.send_replace(Some(collection.id)); - json + serde_json::to_value(status).unwrap_or_else( + |error| json!({ "error": error.to_string() }), + ) } } } @@ -120,7 +125,7 @@ async fn inventory_activate( nkeep: u32, disabled: bool, cockroach_admin_client: &CockroachClusterAdminClient, -) -> Result { +) -> Result<(Collection, Vec), anyhow::Error> { // If we're disabled, don't do anything. (This switch is only intended for // unforeseen production emergencies.) ensure!(!disabled, "disabled by explicit configuration"); @@ -211,7 +216,7 @@ async fn inventory_activate( &sled_enum, opctx.log.clone(), ); - let collection = + let (collection, spans) = inventory.collect_all().await.context("collecting inventory")?; // Write it to the database. @@ -220,7 +225,7 @@ async fn inventory_activate( .await .context("saving inventory to database")?; - Ok(collection) + Ok((collection, spans)) } /// Determine which sleds to inventory based on what's in the database @@ -269,6 +274,7 @@ mod test { use nexus_inventory::SledAgentEnumerator; use nexus_test_utils_macros::nexus_test; use nexus_types::identity::Asset; + use nexus_types::internal_api::background::InventoryCollectionStatus; use omicron_common::api::external::ByteCount; use omicron_common::api::external::LookupType; use omicron_uuid_kinds::CollectionUuid; @@ -313,7 +319,16 @@ mod test { let nkeep = usize::try_from(nkeep).unwrap(); let mut all_our_collection_ids = Vec::new(); for i in 0..20 { - let _ = task.activate(&opctx).await; + let value = task.activate(&opctx).await; + + // The status should include a timing trace with at least one + // event per collection phase. + let status: InventoryCollectionStatus = + serde_json::from_value(value) + .expect("failed to parse activation status"); + let trace = status.trace.expect("status should include a trace"); + assert!(trace.trace_events.len() >= 6); + let collections = datastore.inventory_collections().await.unwrap(); // Nexus is creating inventory collections concurrently with us, diff --git a/nexus/types/Cargo.toml b/nexus/types/Cargo.toml index 331e64835c8..d5aaa403688 100644 --- a/nexus/types/Cargo.toml +++ b/nexus/types/Cargo.toml @@ -40,6 +40,7 @@ oximeter-db.workspace = true oxnet.workspace = true oxql-types.workspace = true parse-display.workspace = true +perfetto-trace.workspace = true regex.workspace = true schemars = { workspace = true, features = ["chrono", "uuid1", "url"] } serde.workspace = true diff --git a/nexus/types/src/internal_api/background.rs b/nexus/types/src/internal_api/background.rs index 1e75a925929..73d95022161 100644 --- a/nexus/types/src/internal_api/background.rs +++ b/nexus/types/src/internal_api/background.rs @@ -725,6 +725,23 @@ impl slog::KV for DatasetsRendezvousStats { } } +/// The status of a successful `inventory_collection` background task +/// activation. +#[derive(Clone, Debug, Deserialize, Serialize, PartialEq)] +pub struct InventoryCollectionStatus { + pub collection_id: CollectionUuid, + pub time_started: DateTime, + pub time_done: DateTime, + + /// Timing of the collection's phases and requests, in the Chrome Trace + /// Event format (load into ). + /// + /// Optional so that this type can also represent status reported by + /// versions of Nexus that did not record a trace. + #[serde(default, skip_serializing_if = "Option::is_none")] + pub trace: Option, +} + /// The status of an `inventory_load` background task activation. #[derive(Clone, Debug, Deserialize, Serialize, PartialEq, Eq)] pub enum InventoryLoadStatus { From 7eae0109d8a258e6a35b7048b9b6a2bcfd7964bf Mon Sep 17 00:00:00 2001 From: Sean Klein Date: Thu, 6 Aug 2026 15:51:47 -0700 Subject: [PATCH 3/3] omdb: show inventory phase timings and export the collection trace The inventory_collection task printer now deserializes the shared InventoryCollectionStatus type and prints per-phase durations when the status includes a trace. A new subcommand, omdb nexus background-tasks inventory-trace --output writes the last collection's full trace as Chrome Trace Event format JSON for loading into https://ui.perfetto.dev/. --- dev-tools/omdb/src/bin/omdb/nexus.rs | 82 ++++++++++++++++++++++++--- dev-tools/omdb/tests/successes.out | 16 ++++++ dev-tools/omdb/tests/usage_errors.out | 13 +++-- 3 files changed, 97 insertions(+), 14 deletions(-) diff --git a/dev-tools/omdb/src/bin/omdb/nexus.rs b/dev-tools/omdb/src/bin/omdb/nexus.rs index aedd47acc6c..53a329068a2 100644 --- a/dev-tools/omdb/src/bin/omdb/nexus.rs +++ b/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 + /// 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, - time_done: DateTime, - } - - match serde_json::from_value::(details.clone()) { + match serde_json::from_value::(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`)" + ); + } } }; } diff --git a/dev-tools/omdb/tests/successes.out b/dev-tools/omdb/tests/successes.out index 129371ef432..967efb2e1b4 100644 --- a/dev-tools/omdb/tests/successes.out +++ b/dev-tools/omdb/tests/successes.out @@ -859,6 +859,14 @@ task: "inventory_collection" last collection id: ..................... last collection started: last collection done: + phase timings: + mgs: ms + sled_agents: ms + keepers: ms + cockroach: ms + timesync: ms + dns_generations: ms + (fetch the full trace with `omdb nexus background-tasks inventory-trace`) task: "inventory_loader" configured period: every s @@ -1584,6 +1592,14 @@ task: "inventory_collection" last collection id: ..................... last collection started: last collection done: + phase timings: + mgs: ms + sled_agents: ms + keepers: ms + cockroach: ms + timesync: ms + dns_generations: ms + (fetch the full trace with `omdb nexus background-tasks inventory-trace`) task: "inventory_loader" configured period: every s diff --git a/dev-tools/omdb/tests/usage_errors.out b/dev-tools/omdb/tests/usage_errors.out index 0cbb3bb455a..f72035266ab 100644 --- a/dev-tools/omdb/tests/usage_errors.out +++ b/dev-tools/omdb/tests/usage_errors.out @@ -1419,12 +1419,13 @@ print information about background tasks Usage: omdb nexus background-tasks [OPTIONS] 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 filter [env: LOG_LEVEL=] [default: warn]