diff --git a/rust/conduit/src/bep/router.rs b/rust/conduit/src/bep/router.rs index 5a24039..344505f 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) => { @@ -574,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, }); @@ -975,6 +986,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.rs b/rust/conduit/src/otel/mapper.rs index 97131c7..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, } @@ -290,6 +292,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 +438,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 +644,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 +767,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 +927,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/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/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..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. @@ -312,12 +317,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 +355,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..9cc6705 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] @@ -1021,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", @@ -1054,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] @@ -1196,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.