From f6accce59d7cc8b21c0351a9867ca8ae77d30722 Mon Sep 17 00:00:00 2001 From: Joseph Gette Date: Mon, 2 Nov 2026 15:50:43 +0100 Subject: [PATCH 1/3] Stop the skipped-targets span from spanning the build The group span opened at the invocation start and closed at the build end, while every skipped target inside it is zero-length, so a build with skipped targets reported them as taking the whole build. Skipped targets take no time, but Bazel reports them both during analysis and after execution, so a first-to-last window would still span the build. Put every skipped target and the group at the first skip's timestamp, kept inside the invocation. Remove the uncalled on_aborted_label, which built the same group the old way. --- rust/conduit/src/otel/mapper.rs | 16 +++---- rust/conduit/src/otel/mapper/lifecycle.rs | 51 +---------------------- rust/conduit/src/otel/mapper/targets.rs | 13 ++++-- rust/conduit/src/otel/mapper/tests.rs | 36 ++++++++++++++++ 4 files changed, 57 insertions(+), 59 deletions(-) diff --git a/rust/conduit/src/otel/mapper.rs b/rust/conduit/src/otel/mapper.rs index 97131c7..5dce095 100644 --- a/rust/conduit/src/otel/mapper.rs +++ b/rust/conduit/src/otel/mapper.rs @@ -290,6 +290,9 @@ pub struct OtelMapper { /// Created lazily on first skipped target, ended in [`finish`]. skipped_context: Option, + /// Timestamp shared by every skipped target and the `skipped` span. + skipped_at: Option, + /// Cached configurations: config hash → mnemonic (e.g. `k8-fastbuild`). configurations: HashMap, @@ -433,6 +436,7 @@ impl OtelMapper { target_start_nanos: HashMap::new(), closed_targets: HashSet::new(), skipped_context: None, + skipped_at: None, configurations: HashMap::new(), cached_command: None, cached_patterns: Vec::new(), @@ -638,11 +642,8 @@ impl OtelMapper { let mut builder = tracer .span_builder(name) .with_kind(SpanKind::Internal); - // Anchor group spans at the invocation start. They are created - // lazily on their first child, which can arrive late (e.g. the - // first skipped target on an interrupted build); without an - // explicit start the span would begin at "now" and a child whose - // event time predates creation would fall outside the parent. + // Without an explicit start the span would begin at "now", after + // its first child's event time when events are processed late. if let Some(nanos) = start_nanos { builder = builder.with_start_time(nanos_to_system_time(nanos)); } @@ -764,6 +765,7 @@ impl OtelMapper { if let Some(cx) = self.skipped_context.take() { cx.span().end(); } + self.skipped_at = None; for (_, cx) in self.target_contexts.drain() { cx.span().end(); } @@ -923,10 +925,10 @@ impl OtelMapper { } self.configured_targets.clear(); - // End the `skipped targets` parent span. if let Some(cx) = self.skipped_context.take() { cx.span().set_status(Status::Unset); - if let Some(nanos) = effective_end { + let end = self.skipped_at.take().or(effective_end); + if let Some(nanos) = end { cx.span().end_with_timestamp(nanos_to_system_time(nanos)); } else { cx.span().end(); diff --git a/rust/conduit/src/otel/mapper/lifecycle.rs b/rust/conduit/src/otel/mapper/lifecycle.rs index 214860c..3340058 100644 --- a/rust/conduit/src/otel/mapper/lifecycle.rs +++ b/rust/conduit/src/otel/mapper/lifecycle.rs @@ -3,11 +3,11 @@ use std::collections::HashMap; use std::path::PathBuf; -use tracing::{debug, info, warn}; +use tracing::{info, warn}; use super::super::attributes::*; use super::{ExecLogState, OtelMapper}; -use crate::otel::span::{self, Context, KeyValue, SpanContext, SpanId, SpanKind, Status}; +use crate::otel::span::{self, Context, KeyValue, SpanContext, SpanId, SpanKind}; impl OtelMapper { /// BuildStarted -> create root span `bazel.invocation`, starting at the @@ -188,53 +188,6 @@ impl OtelMapper { } } - /// UnconfiguredLabel / ConfiguredLabel with Aborted payload -> - /// record as a span under the "skipped" parent (root-cause failure). - pub fn on_aborted_label( - &mut self, - label: &str, - reason: Option<&str>, - description: Option<&str>, - event_time_nanos: Option, - ) { - Self::ensure_group_span( - &mut self.skipped_context, - &self.root_context, - &self.tracer, - "skipped targets", - self.root_span_start_nanos, - ); - - let Some(parent) = &self.skipped_context else { - return; - }; - - let short = shorten_label(label); - let mut attrs = vec![ - KeyValue::new(BAZEL_TARGET_LABEL, label.to_string()), - KeyValue::new(BAZEL_TARGET_SUCCESS, false), - ]; - if let Some(r) = reason { - attrs.push(KeyValue::new(BAZEL_TARGET_ABORT_REASON, r.to_string())); - } - if let Some(d) = description { - attrs.push(KeyValue::new(BAZEL_TARGET_ABORT_DESCRIPTION, d.to_string())); - } - - self.build_and_end_child_span( - parent, - format!("target {short}"), - SpanKind::Internal, - attrs, - Status::Error { - description: std::borrow::Cow::Owned(description.unwrap_or("aborted").to_string()), - }, - None, - event_time_nanos, - ); - debug!("Created aborted-label span for {label}"); - } - /// Configuration -> cache its mnemonic (e.g. `k8-fastbuild`) for actions. pub fn on_configuration(&mut self, config_id: &str, mnemonic: &str) { if !mnemonic.is_empty() { diff --git a/rust/conduit/src/otel/mapper/targets.rs b/rust/conduit/src/otel/mapper/targets.rs index 23ea0bd..0ab7ee7 100644 --- a/rust/conduit/src/otel/mapper/targets.rs +++ b/rust/conduit/src/otel/mapper/targets.rs @@ -312,12 +312,20 @@ impl OtelMapper { debug!("Ended leaked target span for {label} on skip"); } + let instant = event_time_nanos.or_else(super::wall_clock_now_nanos); + let (instant, _) = self.clamp_to_invocation(instant, instant); + // Skipped targets take no time, but Bazel reports them both during + // analysis and after execution; one shared instant keeps the group + // from spanning the build. + let instant = self.skipped_at.or(instant); + self.skipped_at = instant; + Self::ensure_group_span( &mut self.skipped_context, &self.root_context, &self.tracer, "skipped targets", - self.root_span_start_nanos, + instant, ); let parent = match &self.skipped_context { @@ -342,8 +350,7 @@ impl OtelMapper { attrs.push(KeyValue::new(BAZEL_TARGET_ABORT_DESCRIPTION, d.to_string())); } - let (_, clamped_event) = self.clamp_to_invocation(None, event_time_nanos); - let instant = clamped_event + let instant = instant .map(super::nanos_to_system_time) .unwrap_or_else(SystemTime::now); diff --git a/rust/conduit/src/otel/mapper/tests.rs b/rust/conduit/src/otel/mapper/tests.rs index e250d75..eaf693e 100644 --- a/rust/conduit/src/otel/mapper/tests.rs +++ b/rust/conduit/src/otel/mapper/tests.rs @@ -506,6 +506,42 @@ fn test_summary_for_skipped_target_adds_no_span() { assert_eq!(attr_value(targets[0], BAZEL_TARGET_SYNTHETIC), None); } +#[test] +fn skipped_targets_share_one_instant() { + let (mut mapper, collector) = mapper_with_collector(); + // Analysis-time skip, then skips reported after execution and out of order. + mapper.on_target_skipped("//pkg:a", Some("ANALYSIS_FAILURE"), None, Some(20_000_000_000)); + mapper.on_target_skipped("//pkg:b", Some("SKIPPED"), None, Some(190_000_000_000)); + mapper.on_target_skipped("//pkg:c", Some("SKIPPED"), None, Some(10_000_000_000)); + mapper.on_build_finished(Some(0), Some(200_000_000_000), None); + mapper.finish(); + + let spans = collector.snapshot(); + let first = nanos_to_system_time(20_000_000_000); + let group = find_span(&spans, |s| s.name == "skipped targets").expect("skipped group"); + assert_eq!((group.start_time, group.end_time), (first, first)); + let children: Vec<_> = spans.iter().filter(|s| s.name.starts_with("target //pkg:")).collect(); + assert_eq!(children.len(), 3); + for child in children { + assert_eq!(child.parent_span_id, group.span_context.span_id()); + assert_eq!((child.start_time, child.end_time), (first, first), "{}", child.name); + } +} + +#[test] +fn skipped_target_before_build_start_stays_inside_root() { + let (mut mapper, collector) = mapper_with_collector(); + mapper.on_target_skipped("//pkg:early", Some("SKIPPED"), None, Some(500_000_000)); + mapper.finish(); + + let spans = collector.snapshot(); + let root = find_span(&spans, |s| s.parent_span_id == SpanId::INVALID).expect("root span"); + let group = find_span(&spans, |s| s.name == "skipped targets").expect("skipped group"); + let child = find_span(&spans, |s| s.name == "target //pkg:early").expect("skipped target"); + assert_eq!(group.start_time, root.start_time); + assert_eq!(child.start_time, root.start_time); +} + /// Events after `TargetCompleted` (late actions, tests and their summary) /// land on the real target span, which completes at finish. #[test] From 1fe6fbefc3ffc5acee568b5d9fcc3ee5275318f8 Mon Sep 17 00:00:00 2001 From: Joseph Gette Date: Mon, 2 Nov 2026 16:01:07 +0100 Subject: [PATCH 2/3] Record skipped targets reported only via TargetConfigured Bazel 9 reports targets that fail analysis through aborted TargetConfigured events, often without a matching ConfiguredLabel event, so some skipped targets never got a span. Route those events to on_target_skipped and ignore a second report for a target that is already skipped. Refs #6 --- rust/conduit/src/bep/router.rs | 58 +++++++++++++++++++++++++ rust/conduit/src/otel/mapper/targets.rs | 5 +++ 2 files changed, 63 insertions(+) diff --git a/rust/conduit/src/bep/router.rs b/rust/conduit/src/bep/router.rs index 5a24039..f183db4 100644 --- a/rust/conduit/src/bep/router.rs +++ b/rust/conduit/src/bep/router.rs @@ -501,6 +501,16 @@ impl EventRouter { ); } } + if let Some(BepPayload::Aborted(a)) = &event.payload { + if let Some(mapper) = &mut self.mapper { + mapper.on_target_skipped( + &t.label, + Some(a.reason().as_str_name()), + Some(a.description.as_str()), + event_time_nanos, + ); + } + } Ok(()) } BepId::TargetCompleted(t) => { @@ -975,6 +985,54 @@ mod tests { assert_eq!(root.end_time, UNIX_EPOCH + Duration::from_secs(105), "no BuildFinished: root ends on the build clock"); } + #[test] + fn every_skipped_target_gets_one_span() { + use crate::build_event_stream::build_event::Payload; + use crate::build_event_stream::build_event_id::{ConfiguredLabelId, Id, TargetConfiguredId}; + use crate::build_event_stream::aborted::AbortReason; + use crate::build_event_stream::{Aborted, BuildEvent, BuildEventId, BuildStarted}; + use crate::otel::span::{Sink, Tracer}; + use crate::otel::OtelMapper; + + let event = |id: Id, payload: Payload| BuildEvent { + id: Some(BuildEventId { id: Some(id) }), + payload: Some(payload), + ..Default::default() + }; + let aborted = || { + Payload::Aborted(Aborted { reason: AbortReason::AnalysisFailure as i32, ..Default::default() }) + }; + let configured = |label: &str| { + event(Id::TargetConfigured(TargetConfiguredId { label: label.into(), ..Default::default() }), aborted()) + }; + let started = event( + Id::Started(Default::default()), + Payload::Started(BuildStarted { uuid: "u".into(), command: "build".into(), ..Default::default() }), + ); + + let (sink, spans) = Sink::memory(); + let mut router = super::EventRouter::new().with_mapper(OtelMapper::new(Tracer::new(sink), None)); + // Bazel 9 order for an analysis failure and the target that depends on it. + for ev in [ + started, + event(Id::ConfiguredLabel(ConfiguredLabelId { label: "//:broken".into(), ..Default::default() }), aborted()), + configured("//:broken"), + configured("//:needs_broken"), + ] { + router.route_build_event(&ev, None).unwrap(); + } + router.finish(); + + let mut skipped: Vec = spans + .snapshot() + .into_iter() + .map(|s| s.name.to_string()) + .filter(|n| n.starts_with("target ")) + .collect(); + skipped.sort(); + assert_eq!(skipped, ["target //:broken", "target //:needs_broken"]); + } + #[test] fn test_status_names() { assert_eq!(test_status_name(1), "PASSED"); diff --git a/rust/conduit/src/otel/mapper/targets.rs b/rust/conduit/src/otel/mapper/targets.rs index 0ab7ee7..98cf141 100644 --- a/rust/conduit/src/otel/mapper/targets.rs +++ b/rust/conduit/src/otel/mapper/targets.rs @@ -303,6 +303,11 @@ impl OtelMapper { description: Option<&str>, event_time_nanos: Option, ) { + // Bazel can report one skipped target twice (ConfiguredLabel and + // TargetConfigured). Completed targets only close at finish. + if self.closed_targets.contains(label) { + return; + } // Consume the configured metadata (if any). let configured = self.configured_targets.remove(label); // End any open span from target_contexts to avoid leaks. From 1bdc03276ce11e2091b82241deee5d97b4ac1518 Mon Sep 17 00:00:00 2001 From: Joseph Gette Date: Mon, 2 Nov 2026 16:07:59 +0100 Subject: [PATCH 3/3] Place cache-hit actions at the time Bazel reports them Bazel reports a cache hit with the start and end time of the run that filled the cache. Conduit kept that duration and shifted it to the build start, so cache hits showed minutes of work they never did and won the lightweight span budget over real slow actions. A cache hit (cached == true, or, before Bazel 10, an action starting before the build) is now a zero-length span at the time Bazel reported it, and ranks as zero duration in the budget. An explicit cache miss keeps its timing. Refs #6 --- rust/conduit/src/bep/router.rs | 1 + rust/conduit/src/otel/mapper.rs | 2 + rust/conduit/src/otel/mapper/actions.rs | 31 +++++++-- rust/conduit/src/otel/mapper/tests.rs | 91 +++++++++++++++++++++++-- 4 files changed, 114 insertions(+), 11 deletions(-) diff --git a/rust/conduit/src/bep/router.rs b/rust/conduit/src/bep/router.rs index f183db4..344505f 100644 --- a/rust/conduit/src/bep/router.rs +++ b/rust/conduit/src/bep/router.rs @@ -584,6 +584,7 @@ impl EventRouter { start_time_nanos: start_nanos, // Internal actions (Symlink, ...) carry no times. end_time_nanos: end_nanos.or(event_time_nanos), + event_time_nanos, cached, runner, }); diff --git a/rust/conduit/src/otel/mapper.rs b/rust/conduit/src/otel/mapper.rs index 5dce095..004fc97 100644 --- a/rust/conduit/src/otel/mapper.rs +++ b/rust/conduit/src/otel/mapper.rs @@ -83,6 +83,8 @@ pub struct ActionCompletedEvent { pub stderr_path: Option, pub start_time_nanos: Option, pub end_time_nanos: Option, + /// When Bazel reported the action in this build. + pub event_time_nanos: Option, pub cached: Option, pub runner: Option, } diff --git a/rust/conduit/src/otel/mapper/actions.rs b/rust/conduit/src/otel/mapper/actions.rs index 4b3990c..77b55a9 100644 --- a/rust/conduit/src/otel/mapper/actions.rs +++ b/rust/conduit/src/otel/mapper/actions.rs @@ -27,7 +27,7 @@ impl OtelMapper { self.emit_action(&ev); return; } - let duration_nanos = match (ev.start_time_nanos, ev.end_time_nanos) { + let duration_nanos = match self.action_time_range(&ev) { (Some(start), Some(end)) => (end - start).max(0), _ => 0, }; @@ -54,13 +54,35 @@ impl OtelMapper { .into_iter() .map(|Reverse(b)| b.event) .collect(); - kept.sort_by_key(|ev| ev.start_time_nanos.or(ev.end_time_nanos)); + kept.sort_by_key(|ev| { + let (start, end) = self.action_time_range(ev); + start.or(end) + }); for ev in &kept { self.emit_action(ev); } kept.len() } + /// Bazel reports a cache hit with the timing of the run that filled the + /// cache. Such an action took no time in this build, so it is placed at + /// the moment Bazel reported it. Before Bazel 10 `cached` is unknown, and + /// a start before the build is the only sign of a cache hit. + fn action_time_range(&self, ev: &ActionCompletedEvent) -> (Option, Option) { + let cached = ev.cached.unwrap_or_else(|| { + matches!( + (ev.start_time_nanos, self.root_span_start_nanos), + (Some(start), Some(root_start)) if start < root_start + ) + }); + if cached { + let at = ev.event_time_nanos.or(ev.end_time_nanos); + (at, at) + } else { + (ev.start_time_nanos, ev.end_time_nanos) + } + } + /// Create the `action {mnemonic} {label}` span. With the compact exec log /// enabled the span is kept open so arriving spawns can backfill attrs /// onto it; without it the span ends here. @@ -72,9 +94,10 @@ impl OtelMapper { // Clamp action timing before creating a synthetic target so its // lifecycle can use the same child bounds. + let (start, end) = self.action_time_range(ev); let (clamped_start, clamped_end) = clamp_time_range( - ev.start_time_nanos, - ev.end_time_nanos, + start, + end, self.root_span_start_nanos, self.root_span_end_from_wall_nanos.or(self.finish_time_nanos), ); diff --git a/rust/conduit/src/otel/mapper/tests.rs b/rust/conduit/src/otel/mapper/tests.rs index eaf693e..9cc6705 100644 --- a/rust/conduit/src/otel/mapper/tests.rs +++ b/rust/conduit/src/otel/mapper/tests.rs @@ -1057,11 +1057,12 @@ fn cached_spawn_chain_is_nested_inside_root_window() { mapper.root_span_end_from_wall_nanos = Some(invocation_start + 2_000_000_000); mapper.compact_streaming_active = true; - mapper.on_action_completed(action_event_for( - "//pkg:cached", - "GoCompilePkg", - "bazel-out/cached.a", - )); + let reported_at = invocation_start + 1_000_000_000; + mapper.on_action_completed(ActionCompletedEvent { + event_time_nanos: Some(reported_at), + cached: None, + ..action_event_for("//pkg:cached", "GoCompilePkg", "bazel-out/cached.a") + }); mapper.on_compact_spawn(spawn_exec_with_metrics( "//pkg:cached", "GoCompilePkg", @@ -1090,8 +1091,8 @@ fn cached_spawn_chain_is_nested_inside_root_window() { assert!(action.end_time <= target.end_time); assert!(target.end_time <= root.end_time); assert_eq!(target.end_time, action.end_time); - assert!(action.start_time < action.end_time); - assert!(spawn.start_time < spawn.end_time); + assert_eq!(action.start_time, nanos_to_system_time(reported_at)); + assert_eq!(action.end_time, nanos_to_system_time(reported_at)); } #[test] @@ -1232,6 +1233,82 @@ fn lightweight_budget_keeps_slowest_successes_and_all_failures() { ); } +/// An action timed before the build started is a cache hit replaying an +/// older run, even when Bazel does not say it was cached. +#[test] +fn action_predating_build_is_placed_at_report_time() { + let (mut mapper, collector) = mapper_with_collector(); + mapper.on_action_completed(ActionCompletedEvent { + start_time_nanos: Some(200_000_000), + end_time_nanos: Some(800_000_000), + event_time_nanos: Some(3_000_000_000), + cached: None, + ..action_event_for("//:old", "Genrule", "bazel-out/old") + }); + mapper.finish(); + + let spans = collector.snapshot(); + let action = find_span(&spans, |s| s.name == "action Genrule //:old").expect("action span"); + assert_eq!(action.start_time, nanos_to_system_time(3_000_000_000)); + assert_eq!(action.end_time, nanos_to_system_time(3_000_000_000)); +} + +#[test] +fn cached_action_inside_build_takes_no_time() { + let (mut mapper, collector) = mapper_with_collector(); + mapper.on_action_completed(ActionCompletedEvent { + start_time_nanos: Some(2_000_000_000), + end_time_nanos: Some(4_000_000_000), + event_time_nanos: Some(4_500_000_000), + cached: Some(true), + ..action_event_for("//:hit", "Genrule", "bazel-out/hit") + }); + mapper.finish(); + + let spans = collector.snapshot(); + let action = find_span(&spans, |s| s.name == "action Genrule //:hit").expect("action span"); + assert_eq!(action.start_time, nanos_to_system_time(4_500_000_000)); + assert_eq!(action.end_time, nanos_to_system_time(4_500_000_000)); +} + +/// An explicit cache miss keeps its timing even if its clock runs behind. +#[test] +fn reported_cache_miss_keeps_its_duration() { + let (mut mapper, collector) = mapper_with_collector(); + mapper.on_action_completed(ActionCompletedEvent { + start_time_nanos: Some(900_000_000), + end_time_nanos: Some(3_000_000_000), + event_time_nanos: Some(3_100_000_000), + cached: Some(false), + ..action_event_for("//:miss", "Genrule", "bazel-out/miss") + }); + mapper.finish(); + + let spans = collector.snapshot(); + let action = find_span(&spans, |s| s.name == "action Genrule //:miss").expect("action span"); + assert_eq!(action.start_time, nanos_to_system_time(1_000_000_000)); + assert_eq!(action.end_time, nanos_to_system_time(3_000_000_000)); +} + +/// A cache hit's original runtime must not win the budget over real work. +#[test] +fn lightweight_budget_ranks_cache_hits_as_instant() { + let (mut mapper, collector) = mapper_with_collector(); + mapper.set_trace_policy(TracePolicy::new(TraceProfile::Lightweight, 500, 1)); + + mapper.on_action_completed(ActionCompletedEvent { + start_time_nanos: Some(-60_000_000_000), + end_time_nanos: Some(0), + event_time_nanos: Some(2_000_000_000), + cached: None, + ..action_event_for("//:hit", "Genrule", "bazel-out/hit") + }); + mapper.on_action_completed(timed_action("//:work", true, 50)); + mapper.finish(); + + assert_eq!(action_names(&collector.snapshot()), ["action Genrule //:work"]); +} + /// A successful target completes after the budget settles: it survives /// (with its configured kind) when one of its actions was kept, and is /// suppressed as empty when all of them were dropped.