From f13facb7f9375e4b8fd5cf5e38d3fe799c420624 Mon Sep 17 00:00:00 2001 From: Tony Xiao Date: Mon, 23 Aug 2021 13:20:43 -0400 Subject: [PATCH 1/9] feat(suspect-spans): Add span exclusive time This change adds the computation for the span's exclusive time if it is enabled. The span's exclusive time can be understood as the amount of time spent in this span excluding the time spent in any immediate children. --- relay-general/src/protocol/contexts.rs | 2 +- relay-general/src/protocol/span.rs | 4 + relay-general/src/store/mod.rs | 3 + relay-general/src/store/normalize.rs | 8 + relay-general/src/store/normalize/spans.rs | 656 +++++++++++++++++++++ relay-server/src/actors/envelopes.rs | 1 + relay-server/src/actors/project.rs | 4 + 7 files changed, 677 insertions(+), 1 deletion(-) create mode 100644 relay-general/src/store/normalize/spans.rs diff --git a/relay-general/src/protocol/contexts.rs b/relay-general/src/protocol/contexts.rs index 951313b80f..2cec5ae75b 100644 --- a/relay-general/src/protocol/contexts.rs +++ b/relay-general/src/protocol/contexts.rs @@ -442,7 +442,7 @@ impl FromValue for TraceId { } /// A 16-character hex string as described in the W3C trace context spec. -#[derive(Clone, Debug, Default, PartialEq, Empty, IntoValue, ProcessValue)] +#[derive(Clone, Debug, Default, Eq, Hash, PartialEq, Empty, IntoValue, ProcessValue)] #[cfg_attr(feature = "jsonschema", derive(JsonSchema))] pub struct SpanId(pub String); diff --git a/relay-general/src/protocol/span.rs b/relay-general/src/protocol/span.rs index 981427fb73..998fd1b438 100644 --- a/relay-general/src/protocol/span.rs +++ b/relay-general/src/protocol/span.rs @@ -13,6 +13,8 @@ pub struct Span { #[metastructure(required = "true")] pub start_timestamp: Annotated, + pub exclusive_time: Annotated, + /// Human readable description of a span (e.g. method URL). #[metastructure(pii = "maybe")] pub description: Annotated, @@ -59,6 +61,7 @@ mod tests { let json = r#"{ "timestamp": 0.0, "start_timestamp": -63158400.0, + "exclusive_time": 1.23, "description": "desc", "op": "operation", "span_id": "fa90fdead5f74052", @@ -69,6 +72,7 @@ mod tests { let span = Annotated::new(Span { timestamp: Annotated::new(Utc.ymd(1970, 1, 1).and_hms_nano(0, 0, 0, 0).into()), start_timestamp: Annotated::new(Utc.ymd(1968, 1, 1).and_hms_nano(0, 0, 0, 0).into()), + exclusive_time: Annotated::new(1.23), description: Annotated::new("desc".to_owned()), op: Annotated::new("operation".to_owned()), trace_id: Annotated::new(TraceId("4c79f60c11214eb38604f4ae0781bfb2".into())), diff --git a/relay-general/src/store/mod.rs b/relay-general/src/store/mod.rs index 2f8bff3295..77d8ae3903 100644 --- a/relay-general/src/store/mod.rs +++ b/relay-general/src/store/mod.rs @@ -1,4 +1,5 @@ //! Utility code for sentry's internal store. +use std::collections::BTreeSet; use std::sync::Arc; use chrono::{DateTime, Utc}; @@ -53,6 +54,8 @@ pub struct StoreConfig { /// Emit breakdowns based on given configuration. pub breakdowns: Option, + + pub span_attributes: BTreeSet, } /// The processor that normalizes events for store. diff --git a/relay-general/src/store/normalize.rs b/relay-general/src/store/normalize.rs index 66377c9a47..f624be7828 100644 --- a/relay-general/src/store/normalize.rs +++ b/relay-general/src/store/normalize.rs @@ -26,6 +26,7 @@ mod contexts; mod logentry; mod mechanism; mod request; +mod spans; mod stacktrace; #[cfg(feature = "uaparser")] @@ -111,6 +112,12 @@ impl<'a> NormalizeProcessor<'a> { } } + fn normalize_spans(&self, event: &mut Event) { + if event.ty.value() == Some(&EventType::Transaction) { + spans::normalize_spans(event, &self.config.span_attributes); + } + } + /// Ensures that the `release` and `dist` fields match up. fn normalize_release_dist(&self, event: &mut Event) { if event.dist.value().is_some() && event.release.value().is_empty() { @@ -493,6 +500,7 @@ impl<'a> Processor for NormalizeProcessor<'a> { self.normalize_user_agent(event); self.normalize_measurements(event); self.normalize_breakdowns(event); + self.normalize_spans(event); Ok(()) } diff --git a/relay-general/src/store/normalize/spans.rs b/relay-general/src/store/normalize/spans.rs new file mode 100644 index 0000000000..74a6612af7 --- /dev/null +++ b/relay-general/src/store/normalize/spans.rs @@ -0,0 +1,656 @@ +use std::collections::BTreeSet; +use std::collections::HashMap; + +use crate::protocol::{Event, Span, Timestamp}; +use crate::types::Annotated; + +#[derive(Clone, Debug)] +struct TimeInterval { + start: Timestamp, + end: Timestamp, +} + +impl TimeInterval { + fn new(start: Timestamp, end: Timestamp) -> Self { + if end < start { + TimeInterval { + start: end, + end: start, + } + } else { + TimeInterval { + start: start, + end: end, + } + } + } + + fn get_duration(&self) -> f64 { + let delta: f64 = (self.end.timestamp_nanos() - self.start.timestamp_nanos()) as f64; + // convert to milliseconds (1 ms = 1,000,000 nanoseconds) + (delta / 1_000_000.00).abs() + } +} + +fn merge_non_overlapping_intervals(intervals: &mut Vec) -> Vec { + let mut non_overlapping_intervals = Vec::new(); + + // Make sure that there is at least 1 interval present. + if intervals.is_empty() { + return non_overlapping_intervals; + } + + // Make sure that the intervals are sorted by start time. + intervals.sort_unstable_by_key(|interval| interval.start); + + let mut previous = intervals[0].clone(); + + // The first interval is stored in `previous`, so make sure to skip it. + for current in intervals.iter().skip(1) { + if current.end < previous.end { + // The current interval is completely contained within the + // previous interval, nothing to be done here. + continue; + } else if current.start < previous.end { + // The head of the current interval overlaps with the tail of + // the previous interval, merge the two intervals into one. + previous.end = current.end; + } else { + // The current interval does not intersect with the previous + // interval, finished with the previous interval, and use the + // current interval as the reference going forwards + non_overlapping_intervals.push(previous); + previous = current.clone(); + } + } + + // Make sure to include the final interval. + non_overlapping_intervals.push(previous); + + non_overlapping_intervals +} + +fn interval_exclusive_time(source: &TimeInterval, intervals: &Vec) -> f64 { + let mut exclusive_time = 0.0; + + let mut use_remaining = true; + let mut remaining = source.clone(); + + for interval in intervals { + if interval.end < remaining.start { + // The interval is entirely to the left of the remaining interval, + // so nothing to be done here. + continue; + } else if interval.start >= remaining.end { + // The interval is entirely to the right of the remaining interval, + // so nothing to be done here. + // + // Additionally, since intervals are sorted by start time, all + // intervals afterwards can be skipped. + break; + } else { + // The interval must intersect with the remaining interval in some way. + + if interval.start > remaining.start { + // The interval begins within the remaining interval, there is a + // portion to its left that should be added to the results. + exclusive_time += TimeInterval::new(remaining.start, interval.start).get_duration(); + } + + if interval.end < remaining.end { + // The interval ends within the remaining interval, so the + // tail of the interval interesects with the head of the remaining + // interval. + // + // Subtract the intersection by shifting the start of the remaining + // interval. + remaining.start = interval.end; + } else { + // The interval ends to the right of the remaining interval, so + // the interval intersects with the entirety of the remaining + // interval. + // + // There is nothing remaining to be checked. + use_remaining = false; + break; + } + } + } + + if use_remaining { + exclusive_time += remaining.get_duration(); + } + + exclusive_time +} + +fn get_span_interval(span: &Span) -> Option { + let start_timestamp = span.start_timestamp.value()?.clone(); + let end_timestamp = span.timestamp.value()?.clone(); + Some(TimeInterval::new(start_timestamp, end_timestamp)) +} + +pub fn normalize_spans(event: &mut Event, attributes: &BTreeSet) { + let spans = event.spans.value_mut().get_or_insert_with(|| Vec::new()); + + if attributes.contains("exclusive-time") { + let mut span_map = HashMap::new(); + + for span in spans.iter() { + let span = match span.value() { + None => continue, + Some(span) => span, + }; + + let parent_span_id = match span.parent_span_id.value() { + None => continue, + Some(parent_span_id) => parent_span_id.clone(), + }; + + let interval = match get_span_interval(span) { + None => continue, + Some(interval) => interval, + }; + + span_map + .entry(parent_span_id) + .or_insert_with(Vec::new) + .push(interval) + } + + for span in spans.iter_mut() { + let mut span = match span.value_mut() { + None => continue, + Some(span) => span, + }; + + let span_id = match span.span_id.value() { + None => continue, + Some(span_id) => span_id, + }; + + let span_interval = match get_span_interval(span) { + None => continue, + Some(interval) => interval, + }; + + let child_intervals = match span_map.get_mut(&span_id) { + Some(intervals) => merge_non_overlapping_intervals(intervals), + None => Vec::new(), + }; + + let exclusive_time = interval_exclusive_time(&span_interval, &child_intervals); + span.exclusive_time = Annotated::new(exclusive_time); + } + } +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::protocol::{Event, EventType, Span, SpanId, TraceId}; + use chrono::{TimeZone, Utc}; + use serde_json::json; + + fn make_span( + op: &str, + description: &str, + start_timestamp: Timestamp, + end_timestamp: Timestamp, + span_id: &str, + parent_span_id: &str, + ) -> Annotated { + Annotated::new(Span { + op: Annotated::new(op.into()), + description: Annotated::new(description.into()), + start_timestamp: Annotated::new(start_timestamp), + timestamp: Annotated::new(end_timestamp), + trace_id: Annotated::new(TraceId("4c79f60c11214eb38604f4ae0781bfb2".into())), + span_id: Annotated::new(SpanId(span_id.into())), + parent_span_id: Annotated::new(SpanId(parent_span_id.into())), + ..Default::default() + }) + } + + fn extract_exclusive_time<'a>(span: Span) -> (SpanId, f64) { + ( + span.span_id.into_value().unwrap(), + span.exclusive_time.into_value().unwrap(), + ) + } + + fn extract_span_exclusive_times<'a>(event: Event) -> HashMap { + event + .spans + .into_value() + .unwrap() + .into_iter() + .map(|span| extract_exclusive_time(span.into_value().unwrap())) + .collect() + } + + #[test] + fn test_childless_spans() { + let mut event = Event { + ty: EventType::Transaction.into(), + spans: vec![ + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 1, 0).into(), + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 4, 0).into(), + "bbbbbbbbbbbbbbbb", + "aaaaaaaaaaaaaaaa", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 1, 0).into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 3, 500_000_000) + .into(), + "cccccccccccccccc", + "aaaaaaaaaaaaaaaa", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 3, 0).into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 4, 877_000_000) + .into(), + "dddddddddddddddd", + "aaaaaaaaaaaaaaaa", + ), + ] + .into(), + ..Default::default() + }; + + let config = json!(null); + + normalize_spans(&mut event, &config); + + let exclusive_times = extract_span_exclusive_times(event); + + assert_eq!( + exclusive_times, + vec![ + (SpanId("bbbbbbbbbbbbbbbb".to_string()), 3000.0), + (SpanId("cccccccccccccccc".to_string()), 2500.0), + (SpanId("dddddddddddddddd".to_string()), 1877.0) + ] + .iter() + .cloned() + .collect() + ); + } + + #[test] + fn test_nested_spans() { + let mut event = Event { + ty: EventType::Transaction.into(), + spans: vec![ + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 1, 0).into(), + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 2, 0).into(), + "bbbbbbbbbbbbbbbb", + "aaaaaaaaaaaaaaaa", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 200_000_000) + .into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 800_000_000) + .into(), + "cccccccccccccccc", + "bbbbbbbbbbbbbbbb", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 400_000_000) + .into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 600_000_000) + .into(), + "dddddddddddddddd", + "cccccccccccccccc", + ), + ] + .into(), + ..Default::default() + }; + + let config = json!(null); + + normalize_spans(&mut event, &config); + + let exclusive_times = extract_span_exclusive_times(event); + + assert_eq!( + exclusive_times, + vec![ + (SpanId("bbbbbbbbbbbbbbbb".to_string()), 400.0), + (SpanId("cccccccccccccccc".to_string()), 400.0), + (SpanId("dddddddddddddddd".to_string()), 200.0), + ] + .iter() + .cloned() + .collect() + ); + } + + #[test] + fn test_overlapping_child_spans() { + let mut event = Event { + ty: EventType::Transaction.into(), + spans: vec![ + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 1, 0).into(), + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 2, 0).into(), + "bbbbbbbbbbbbbbbb", + "aaaaaaaaaaaaaaaa", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 200_000_000) + .into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 600_000_000) + .into(), + "cccccccccccccccc", + "bbbbbbbbbbbbbbbb", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 400_000_000) + .into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 800_000_000) + .into(), + "dddddddddddddddd", + "bbbbbbbbbbbbbbbb", + ), + ] + .into(), + ..Default::default() + }; + + let config = json!(null); + + normalize_spans(&mut event, &config); + + let exclusive_times = extract_span_exclusive_times(event); + + assert_eq!( + exclusive_times, + vec![ + (SpanId("bbbbbbbbbbbbbbbb".to_string()), 400.0), + (SpanId("cccccccccccccccc".to_string()), 400.0), + (SpanId("dddddddddddddddd".to_string()), 400.0), + ] + .iter() + .cloned() + .collect() + ); + } + + #[test] + fn test_child_spans_dont_intersect_parent() { + let mut event = Event { + ty: EventType::Transaction.into(), + spans: vec![ + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 1, 0).into(), + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 2, 0).into(), + "bbbbbbbbbbbbbbbb", + "aaaaaaaaaaaaaaaa", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 0, 400_000_000) + .into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 0, 800_000_000) + .into(), + "cccccccccccccccc", + "bbbbbbbbbbbbbbbb", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 2, 200_000_000) + .into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 2, 600_000_000) + .into(), + "dddddddddddddddd", + "bbbbbbbbbbbbbbbb", + ), + ] + .into(), + ..Default::default() + }; + + let config = json!(null); + + normalize_spans(&mut event, &config); + + let exclusive_times = extract_span_exclusive_times(event); + + assert_eq!( + exclusive_times, + vec![ + (SpanId("bbbbbbbbbbbbbbbb".to_string()), 1000.0), + (SpanId("cccccccccccccccc".to_string()), 400.0), + (SpanId("dddddddddddddddd".to_string()), 400.0), + ] + .iter() + .cloned() + .collect() + ); + } + + #[test] + fn test_child_spans_extend_beyond_parent() { + let mut event = Event { + ty: EventType::Transaction.into(), + spans: vec![ + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 1, 0).into(), + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 2, 0).into(), + "bbbbbbbbbbbbbbbb", + "aaaaaaaaaaaaaaaa", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 0, 800_000_000) + .into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 400_000_000) + .into(), + "cccccccccccccccc", + "bbbbbbbbbbbbbbbb", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 600_000_000) + .into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 2, 200_000_000) + .into(), + "dddddddddddddddd", + "bbbbbbbbbbbbbbbb", + ), + ] + .into(), + ..Default::default() + }; + + let config = json!(null); + + normalize_spans(&mut event, &config); + + let exclusive_times = extract_span_exclusive_times(event); + + assert_eq!( + exclusive_times, + vec![ + (SpanId("bbbbbbbbbbbbbbbb".to_string()), 200.0), + (SpanId("cccccccccccccccc".to_string()), 600.0), + (SpanId("dddddddddddddddd".to_string()), 600.0), + ] + .iter() + .cloned() + .collect() + ); + } + + #[test] + fn test_child_spans_consumes_all_of_parent() { + let mut event = Event { + ty: EventType::Transaction.into(), + spans: vec![ + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 1, 0).into(), + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 2, 0).into(), + "bbbbbbbbbbbbbbbb", + "aaaaaaaaaaaaaaaa", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 0, 800_000_000) + .into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 600_000_000) + .into(), + "cccccccccccccccc", + "bbbbbbbbbbbbbbbb", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 400_000_000) + .into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 2, 200_000_000) + .into(), + "dddddddddddddddd", + "bbbbbbbbbbbbbbbb", + ), + ] + .into(), + ..Default::default() + }; + + let config = json!(null); + + normalize_spans(&mut event, &config); + + let exclusive_times = extract_span_exclusive_times(event); + + assert_eq!( + exclusive_times, + vec![ + (SpanId("bbbbbbbbbbbbbbbb".to_string()), 0.0), + (SpanId("cccccccccccccccc".to_string()), 800.0), + (SpanId("dddddddddddddddd".to_string()), 800.0), + ] + .iter() + .cloned() + .collect() + ); + } + + #[test] + fn test_only_immediate_child_spans_affect_calculation() { + let mut event = Event { + ty: EventType::Transaction.into(), + spans: vec![ + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 1, 0).into(), + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 2, 0).into(), + "bbbbbbbbbbbbbbbb", + "aaaaaaaaaaaaaaaa", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 600_000_000) + .into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 2, 200_000_000) + .into(), + "cccccccccccccccc", + "bbbbbbbbbbbbbbbb", + ), + // this should only affect the calculation for it's immediate parent + // which is `cccccccccccccccc` and not `bbbbbbbbbbbbbbbb` + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 400_000_000) + .into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 1, 800_000_000) + .into(), + "dddddddddddddddd", + "cccccccccccccccc", + ), + ] + .into(), + ..Default::default() + }; + + let config = json!(null); + + normalize_spans(&mut event, &config); + + let exclusive_times = extract_span_exclusive_times(event); + + assert_eq!( + exclusive_times, + vec![ + (SpanId("bbbbbbbbbbbbbbbb".to_string()), 600.0), + (SpanId("cccccccccccccccc".to_string()), 400.0), + (SpanId("dddddddddddddddd".to_string()), 400.0), + ] + .iter() + .cloned() + .collect() + ); + } +} diff --git a/relay-server/src/actors/envelopes.rs b/relay-server/src/actors/envelopes.rs index 9fd1cc8c3b..569bfa5793 100644 --- a/relay-server/src/actors/envelopes.rs +++ b/relay-server/src/actors/envelopes.rs @@ -1294,6 +1294,7 @@ impl EnvelopeProcessor { sent_at: envelope.sent_at(), received_at: Some(envelope_context.received_at), breakdowns: project_state.config.breakdowns_v2.clone(), + span_attributes: project_state.config.span_attributes.clone(), }; let mut store_processor = StoreProcessor::new(store_config, self.geoip_lookup.as_deref()); diff --git a/relay-server/src/actors/project.rs b/relay-server/src/actors/project.rs index 8003d9419d..92d314978a 100644 --- a/relay-server/src/actors/project.rs +++ b/relay-server/src/actors/project.rs @@ -84,6 +84,9 @@ pub struct ProjectConfig { /// Configuration for operation breakdown. Will be emitted only if present. #[serde(skip_serializing_if = "Option::is_none")] pub breakdowns_v2: Option, + /// The span attributes configuration. + #[serde(skip_serializing_if = "BTreeSet::is_empty")] + pub span_attributes: BTreeSet, /// Exposable features enabled for this project #[serde(skip_serializing_if = "BTreeSet::is_empty")] pub features: BTreeSet, @@ -102,6 +105,7 @@ impl Default for ProjectConfig { quotas: Vec::new(), dynamic_sampling: None, breakdowns_v2: None, + span_attributes: BTreeSet::new(), features: BTreeSet::new(), } } From 431292046b54c57d29f089f7300b3339b036c236 Mon Sep 17 00:00:00 2001 From: Tony Xiao Date: Mon, 23 Aug 2021 14:07:54 -0400 Subject: [PATCH 2/9] fix tests and add comments --- relay-general/src/store/normalize/spans.rs | 69 ++++++++++++---------- 1 file changed, 37 insertions(+), 32 deletions(-) diff --git a/relay-general/src/store/normalize/spans.rs b/relay-general/src/store/normalize/spans.rs index 74a6612af7..9c47a12428 100644 --- a/relay-general/src/store/normalize/spans.rs +++ b/relay-general/src/store/normalize/spans.rs @@ -18,10 +18,7 @@ impl TimeInterval { end: start, } } else { - TimeInterval { - start: start, - end: end, - } + TimeInterval { start, end } } } @@ -32,7 +29,9 @@ impl TimeInterval { } } -fn merge_non_overlapping_intervals(intervals: &mut Vec) -> Vec { +/// Merge a list of intervals into a list of non overlapping intervals. +/// Assumes that the input intervals are sorted by start time. +fn merge_non_overlapping_intervals(intervals: &mut [TimeInterval]) -> Vec { let mut non_overlapping_intervals = Vec::new(); // Make sure that there is at least 1 interval present. @@ -40,9 +39,6 @@ fn merge_non_overlapping_intervals(intervals: &mut Vec) -> Vec) -> Vec) -> f64 { +/// Computes the exclusive time of the source interval after subtracting the +/// list of intervals. +/// Assumes that the input intervals are sorted by start time. +fn interval_exclusive_time(source: &TimeInterval, intervals: &[TimeInterval]) -> f64 { let mut exclusive_time = 0.0; - let mut use_remaining = true; let mut remaining = source.clone(); for interval in intervals { @@ -108,25 +106,22 @@ fn interval_exclusive_time(source: &TimeInterval, intervals: &Vec) } else { // The interval ends to the right of the remaining interval, so // the interval intersects with the entirety of the remaining - // interval. - // + // interval. So zero out the interval. + remaining.start = remaining.end; + // There is nothing remaining to be checked. - use_remaining = false; break; } } } - if use_remaining { - exclusive_time += remaining.get_duration(); - } - - exclusive_time + // make sure to add the remaining interval + exclusive_time + remaining.get_duration() } fn get_span_interval(span: &Span) -> Option { - let start_timestamp = span.start_timestamp.value()?.clone(); - let end_timestamp = span.timestamp.value()?.clone(); + let start_timestamp = *span.start_timestamp.value()?; + let end_timestamp = *span.timestamp.value()?; Some(TimeInterval::new(start_timestamp, end_timestamp)) } @@ -174,8 +169,12 @@ pub fn normalize_spans(event: &mut Event, attributes: &BTreeSet) { Some(interval) => interval, }; - let child_intervals = match span_map.get_mut(&span_id) { - Some(intervals) => merge_non_overlapping_intervals(intervals), + let child_intervals = match span_map.get_mut(span_id) { + Some(intervals) => { + // Make sure that the intervals are sorted by start time. + intervals.sort_unstable_by_key(|interval| interval.start); + merge_non_overlapping_intervals(intervals) + } None => Vec::new(), }; @@ -190,7 +189,6 @@ mod tests { use super::*; use crate::protocol::{Event, EventType, Span, SpanId, TraceId}; use chrono::{TimeZone, Utc}; - use serde_json::json; fn make_span( op: &str, @@ -212,14 +210,14 @@ mod tests { }) } - fn extract_exclusive_time<'a>(span: Span) -> (SpanId, f64) { + fn extract_exclusive_time(span: Span) -> (SpanId, f64) { ( span.span_id.into_value().unwrap(), span.exclusive_time.into_value().unwrap(), ) } - fn extract_span_exclusive_times<'a>(event: Event) -> HashMap { + fn extract_span_exclusive_times(event: Event) -> HashMap { event .spans .into_value() @@ -267,7 +265,8 @@ mod tests { ..Default::default() }; - let config = json!(null); + let mut config = BTreeSet::new(); + config.insert("exclusive-time".to_string()); normalize_spans(&mut event, &config); @@ -328,7 +327,8 @@ mod tests { ..Default::default() }; - let config = json!(null); + let mut config = BTreeSet::new(); + config.insert("exclusive-time".to_string()); normalize_spans(&mut event, &config); @@ -389,7 +389,8 @@ mod tests { ..Default::default() }; - let config = json!(null); + let mut config = BTreeSet::new(); + config.insert("exclusive-time".to_string()); normalize_spans(&mut event, &config); @@ -450,7 +451,8 @@ mod tests { ..Default::default() }; - let config = json!(null); + let mut config = BTreeSet::new(); + config.insert("exclusive-time".to_string()); normalize_spans(&mut event, &config); @@ -511,7 +513,8 @@ mod tests { ..Default::default() }; - let config = json!(null); + let mut config = BTreeSet::new(); + config.insert("exclusive-time".to_string()); normalize_spans(&mut event, &config); @@ -572,7 +575,8 @@ mod tests { ..Default::default() }; - let config = json!(null); + let mut config = BTreeSet::new(); + config.insert("exclusive-time".to_string()); normalize_spans(&mut event, &config); @@ -635,7 +639,8 @@ mod tests { ..Default::default() }; - let config = json!(null); + let mut config = BTreeSet::new(); + config.insert("exclusive-time".to_string()); normalize_spans(&mut event, &config); From bfbe921f895ba7502d7ad7f315a58b873341eb20 Mon Sep 17 00:00:00 2001 From: Tony Xiao Date: Tue, 24 Aug 2021 11:23:05 -0400 Subject: [PATCH 3/9] more tests --- relay-general/src/store/normalize/spans.rs | 58 ++++++- tests/integration/test_envelope.py | 172 ++++++++++++++++++++- 2 files changed, 227 insertions(+), 3 deletions(-) diff --git a/relay-general/src/store/normalize/spans.rs b/relay-general/src/store/normalize/spans.rs index 9c47a12428..28477e6176 100644 --- a/relay-general/src/store/normalize/spans.rs +++ b/relay-general/src/store/normalize/spans.rs @@ -126,9 +126,9 @@ fn get_span_interval(span: &Span) -> Option { } pub fn normalize_spans(event: &mut Event, attributes: &BTreeSet) { - let spans = event.spans.value_mut().get_or_insert_with(|| Vec::new()); - if attributes.contains("exclusive-time") { + let spans = event.spans.value_mut().get_or_insert_with(|| Vec::new()); + let mut span_map = HashMap::new(); for span in spans.iter() { @@ -227,6 +227,60 @@ mod tests { .collect() } + #[test] + fn test_skip_exclusive_time() { + let mut event = Event { + ty: EventType::Transaction.into(), + spans: vec![ + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 1, 0).into(), + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 4, 0).into(), + "bbbbbbbbbbbbbbbb", + "aaaaaaaaaaaaaaaa", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 1, 0).into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 3, 500_000_000) + .into(), + "cccccccccccccccc", + "aaaaaaaaaaaaaaaa", + ), + make_span( + "db", + "SELECT * FROM table;", + Utc.ymd(2021, 1, 1).and_hms_nano(0, 0, 3, 0).into(), + Utc.ymd(2021, 1, 1) + .and_hms_nano(0, 0, 4, 877_000_000) + .into(), + "dddddddddddddddd", + "aaaaaaaaaaaaaaaa", + ), + ] + .into(), + ..Default::default() + }; + + // do not insert `exclusive-time` + let config = BTreeSet::new(); + + normalize_spans(&mut event, &config); + + let has_exclusive_times: Vec = event + .spans + .into_value() + .unwrap() + .into_iter() + .map(|span| span.into_value().unwrap().exclusive_time.value().is_none()) + .collect(); + + assert_eq!(has_exclusive_times, vec![true, true, true]); + } + #[test] fn test_childless_spans() { let mut event = Event { diff --git a/tests/integration/test_envelope.py b/tests/integration/test_envelope.py index fb86c6c910..c7e8a8830e 100644 --- a/tests/integration/test_envelope.py +++ b/tests/integration/test_envelope.py @@ -207,7 +207,7 @@ def test_ops_breakdowns(mini_sentry, relay_with_processing, transactions_consume transaction_item = generate_transaction_item() transaction_item.update( { - "breakdowns": {"span_ops": {"lcp": {"value": 202.1},}}, + "breakdowns": {"span_ops": {"lcp": {"value": 202.1}}}, "spans": [ { "description": "GET /api/0/organizations/?member=1", @@ -281,6 +281,176 @@ def test_ops_breakdowns(mini_sentry, relay_with_processing, transactions_consume } +def test_no_span_attributes(mini_sentry, relay_with_processing, transactions_consumer): + events_consumer = transactions_consumer() + + relay = relay_with_processing() + config = mini_sentry.add_basic_project_config(42) + + if "spanAttributes" in config["config"]: + del config["config"]["spanAttributes"] + + transaction_item = generate_transaction_item() + transaction_item.update( + { + "spans": [ + { + "description": "GET /api/0/organizations/?member=1", + "op": "http", + "parent_span_id": "aaaaaaaaaaaaaaaa", + "span_id": "bbbbbbbbbbbbbbbb", + "start_timestamp": 1000, + "timestamp": 3000, + "trace_id": "ff62a8b040f340bda5d830223def1d81", + }, + { + "description": "GET /api/0/organizations/?member=1", + "op": "http", + "parent_span_id": "bbbbbbbbbbbbbbbb", + "span_id": "cccccccccccccccc", + "start_timestamp": 1400, + "timestamp": 2600, + "trace_id": "ff62a8b040f340bda5d830223def1d81", + }, + { + "description": "GET /api/0/organizations/?member=1", + "op": "http", + "parent_span_id": "cccccccccccccccc", + "span_id": "dddddddddddddddd", + "start_timestamp": 1700, + "timestamp": 2300, + "trace_id": "ff62a8b040f340bda5d830223def1d81", + }, + ], + } + ) + + envelope = Envelope() + envelope.add_transaction(transaction_item) + relay.send_envelope(42, envelope) + + event, _ = events_consumer.get_event() + assert event["transaction"] == "/organizations/:orgId/performance/:eventSlug/" + assert "trace" in event["contexts"] + for span in event["spans"]: + assert "exclusive_time" not in span + + +def test_empty_span_attributes( + mini_sentry, relay_with_processing, transactions_consumer +): + events_consumer = transactions_consumer() + + relay = relay_with_processing() + config = mini_sentry.add_basic_project_config(42) + + config["config"].setdefault("spanAttributes", []) + + transaction_item = generate_transaction_item() + transaction_item.update( + { + "spans": [ + { + "description": "GET /api/0/organizations/?member=1", + "op": "http", + "parent_span_id": "aaaaaaaaaaaaaaaa", + "span_id": "bbbbbbbbbbbbbbbb", + "start_timestamp": 1000, + "timestamp": 3000, + "trace_id": "ff62a8b040f340bda5d830223def1d81", + }, + { + "description": "GET /api/0/organizations/?member=1", + "op": "http", + "parent_span_id": "bbbbbbbbbbbbbbbb", + "span_id": "cccccccccccccccc", + "start_timestamp": 1400, + "timestamp": 2600, + "trace_id": "ff62a8b040f340bda5d830223def1d81", + }, + { + "description": "GET /api/0/organizations/?member=1", + "op": "http", + "parent_span_id": "cccccccccccccccc", + "span_id": "dddddddddddddddd", + "start_timestamp": 1700, + "timestamp": 2300, + "trace_id": "ff62a8b040f340bda5d830223def1d81", + }, + ], + } + ) + + envelope = Envelope() + envelope.add_transaction(transaction_item) + relay.send_envelope(42, envelope) + + event, _ = events_consumer.get_event() + assert event["transaction"] == "/organizations/:orgId/performance/:eventSlug/" + assert "trace" in event["contexts"] + for span in event["spans"]: + assert "exclusive_time" not in span + + +def test_span_attributes_exclusive_time( + mini_sentry, relay_with_processing, transactions_consumer +): + events_consumer = transactions_consumer() + + relay = relay_with_processing() + config = mini_sentry.add_basic_project_config(42) + + config["config"].setdefault("spanAttributes", ["exclusive-time"]) + + transaction_item = generate_transaction_item() + transaction_item.update( + { + "spans": [ + { + "description": "GET /api/0/organizations/?member=1", + "op": "http", + "parent_span_id": "aaaaaaaaaaaaaaaa", + "span_id": "bbbbbbbbbbbbbbbb", + "start_timestamp": 1000, + "timestamp": 3000, + "trace_id": "ff62a8b040f340bda5d830223def1d81", + }, + { + "description": "GET /api/0/organizations/?member=1", + "op": "http", + "parent_span_id": "bbbbbbbbbbbbbbbb", + "span_id": "cccccccccccccccc", + "start_timestamp": 1400, + "timestamp": 2600, + "trace_id": "ff62a8b040f340bda5d830223def1d81", + }, + { + "description": "GET /api/0/organizations/?member=1", + "op": "http", + "parent_span_id": "cccccccccccccccc", + "span_id": "dddddddddddddddd", + "start_timestamp": 1700, + "timestamp": 2300, + "trace_id": "ff62a8b040f340bda5d830223def1d81", + }, + ], + } + ) + + envelope = Envelope() + envelope.add_transaction(transaction_item) + relay.send_envelope(42, envelope) + + event, _ = events_consumer.get_event() + assert event["transaction"] == "/organizations/:orgId/performance/:eventSlug/" + assert "trace" in event["contexts"] + assert [span["exclusive_time"] for span in event["spans"]] == [ + 800000, + 600000, + 600000, + ] + + def test_sample_rates(mini_sentry, relay_chain): relay = relay_chain(min_relay_version="21.1.0") mini_sentry.add_basic_project_config(42) From 794ac3e95752796823c5d60244575236ffe0c7bd Mon Sep 17 00:00:00 2001 From: Tony Xiao Date: Thu, 26 Aug 2021 12:09:15 -0400 Subject: [PATCH 4/9] address comments --- relay-general/src/protocol/span.rs | 1 + relay-general/src/store/mod.rs | 3 ++- relay-general/src/store/normalize.rs | 2 +- relay-general/src/store/normalize/spans.rs | 30 +++++++++++++++------- relay-server/src/actors/project.rs | 4 +-- 5 files changed, 27 insertions(+), 13 deletions(-) diff --git a/relay-general/src/protocol/span.rs b/relay-general/src/protocol/span.rs index 998fd1b438..bb74cd62f5 100644 --- a/relay-general/src/protocol/span.rs +++ b/relay-general/src/protocol/span.rs @@ -13,6 +13,7 @@ pub struct Span { #[metastructure(required = "true")] pub start_timestamp: Annotated, + /// The amount of time spent in this span, excluding its immediate child spans. pub exclusive_time: Annotated, /// Human readable description of a span (e.g. method URL). diff --git a/relay-general/src/store/mod.rs b/relay-general/src/store/mod.rs index 77d8ae3903..bcfacd38c8 100644 --- a/relay-general/src/store/mod.rs +++ b/relay-general/src/store/mod.rs @@ -23,6 +23,7 @@ mod trimming; pub use self::clock_drift::ClockDriftProcessor; pub use self::geo::{GeoIpError, GeoIpLookup}; pub use normalize::breakdowns::BreakdownsConfig; +pub use normalize::spans::SpanAttribute; /// The config for store. #[derive(Serialize, Deserialize, Debug, Default)] @@ -55,7 +56,7 @@ pub struct StoreConfig { /// Emit breakdowns based on given configuration. pub breakdowns: Option, - pub span_attributes: BTreeSet, + pub span_attributes: BTreeSet, } /// The processor that normalizes events for store. diff --git a/relay-general/src/store/normalize.rs b/relay-general/src/store/normalize.rs index f624be7828..75d10b0a42 100644 --- a/relay-general/src/store/normalize.rs +++ b/relay-general/src/store/normalize.rs @@ -26,7 +26,7 @@ mod contexts; mod logentry; mod mechanism; mod request; -mod spans; +pub mod spans; mod stacktrace; #[cfg(feature = "uaparser")] diff --git a/relay-general/src/store/normalize/spans.rs b/relay-general/src/store/normalize/spans.rs index 28477e6176..70d0491c96 100644 --- a/relay-general/src/store/normalize/spans.rs +++ b/relay-general/src/store/normalize/spans.rs @@ -1,9 +1,21 @@ use std::collections::BTreeSet; use std::collections::HashMap; +use serde::{Deserialize, Serialize}; + use crate::protocol::{Event, Span, Timestamp}; use crate::types::Annotated; +#[derive(Clone, Copy, Debug, Eq, PartialEq, PartialOrd, Ord, Hash, Serialize, Deserialize)] +pub enum SpanAttribute { + #[serde(rename = "exclusive-time")] + ExclusiveTime, + + /// forward compatibility + #[serde(other)] + Unknown, +} + #[derive(Clone, Debug)] struct TimeInterval { start: Timestamp, @@ -125,8 +137,8 @@ fn get_span_interval(span: &Span) -> Option { Some(TimeInterval::new(start_timestamp, end_timestamp)) } -pub fn normalize_spans(event: &mut Event, attributes: &BTreeSet) { - if attributes.contains("exclusive-time") { +pub fn normalize_spans(event: &mut Event, attributes: &BTreeSet) { + if attributes.contains(&SpanAttribute::ExclusiveTime) { let spans = event.spans.value_mut().get_or_insert_with(|| Vec::new()); let mut span_map = HashMap::new(); @@ -320,7 +332,7 @@ mod tests { }; let mut config = BTreeSet::new(); - config.insert("exclusive-time".to_string()); + config.insert(SpanAttribute::ExclusiveTime); normalize_spans(&mut event, &config); @@ -382,7 +394,7 @@ mod tests { }; let mut config = BTreeSet::new(); - config.insert("exclusive-time".to_string()); + config.insert(SpanAttribute::ExclusiveTime); normalize_spans(&mut event, &config); @@ -444,7 +456,7 @@ mod tests { }; let mut config = BTreeSet::new(); - config.insert("exclusive-time".to_string()); + config.insert(SpanAttribute::ExclusiveTime); normalize_spans(&mut event, &config); @@ -506,7 +518,7 @@ mod tests { }; let mut config = BTreeSet::new(); - config.insert("exclusive-time".to_string()); + config.insert(SpanAttribute::ExclusiveTime); normalize_spans(&mut event, &config); @@ -568,7 +580,7 @@ mod tests { }; let mut config = BTreeSet::new(); - config.insert("exclusive-time".to_string()); + config.insert(SpanAttribute::ExclusiveTime); normalize_spans(&mut event, &config); @@ -630,7 +642,7 @@ mod tests { }; let mut config = BTreeSet::new(); - config.insert("exclusive-time".to_string()); + config.insert(SpanAttribute::ExclusiveTime); normalize_spans(&mut event, &config); @@ -694,7 +706,7 @@ mod tests { }; let mut config = BTreeSet::new(); - config.insert("exclusive-time".to_string()); + config.insert(SpanAttribute::ExclusiveTime); normalize_spans(&mut event, &config); diff --git a/relay-server/src/actors/project.rs b/relay-server/src/actors/project.rs index 92d314978a..5ac1bf93d0 100644 --- a/relay-server/src/actors/project.rs +++ b/relay-server/src/actors/project.rs @@ -15,7 +15,7 @@ use relay_common::{metric, ProjectId, ProjectKey}; use relay_config::Config; use relay_filter::{matches_any_origin, FiltersConfig}; use relay_general::pii::{DataScrubbingConfig, PiiConfig}; -use relay_general::store::BreakdownsConfig; +use relay_general::store::{BreakdownsConfig, SpanAttribute}; use relay_metrics::{self, Aggregator, Bucket, Metric}; use relay_quotas::{Quota, RateLimits, Scoping}; use relay_sampling::SamplingConfig; @@ -86,7 +86,7 @@ pub struct ProjectConfig { pub breakdowns_v2: Option, /// The span attributes configuration. #[serde(skip_serializing_if = "BTreeSet::is_empty")] - pub span_attributes: BTreeSet, + pub span_attributes: BTreeSet, /// Exposable features enabled for this project #[serde(skip_serializing_if = "BTreeSet::is_empty")] pub features: BTreeSet, From 2d0bb3461d483922b7965ea3b9bb14339a52db20 Mon Sep 17 00:00:00 2001 From: Tony Xiao Date: Mon, 30 Aug 2021 11:44:53 -0400 Subject: [PATCH 5/9] address some PR comments --- relay-general/src/protocol/span.rs | 3 +- relay-general/src/store/mod.rs | 4 +- relay-general/src/store/normalize/spans.rs | 126 ++++++++++----------- relay-general/src/types/mod.rs | 2 + relay-general/src/types/span_attributes.rs | 12 ++ relay-server/src/actors/project.rs | 3 +- 6 files changed, 81 insertions(+), 69 deletions(-) create mode 100644 relay-general/src/types/span_attributes.rs diff --git a/relay-general/src/protocol/span.rs b/relay-general/src/protocol/span.rs index bb74cd62f5..dcb57e16c5 100644 --- a/relay-general/src/protocol/span.rs +++ b/relay-general/src/protocol/span.rs @@ -13,7 +13,8 @@ pub struct Span { #[metastructure(required = "true")] pub start_timestamp: Annotated, - /// The amount of time spent in this span, excluding its immediate child spans. + /// The amount of time in milliseconds spent in this span, + /// excluding its immediate child spans. pub exclusive_time: Annotated, /// Human readable description of a span (e.g. method URL). diff --git a/relay-general/src/store/mod.rs b/relay-general/src/store/mod.rs index bcfacd38c8..58639923de 100644 --- a/relay-general/src/store/mod.rs +++ b/relay-general/src/store/mod.rs @@ -8,7 +8,7 @@ use serde_json::Value; use crate::processor::{ProcessingState, Processor}; use crate::protocol::{Event, IpAddr}; -use crate::types::{Meta, ProcessingResult}; +use crate::types::{Meta, ProcessingResult, SpanAttribute}; mod clock_drift; mod event_error; @@ -23,7 +23,6 @@ mod trimming; pub use self::clock_drift::ClockDriftProcessor; pub use self::geo::{GeoIpError, GeoIpLookup}; pub use normalize::breakdowns::BreakdownsConfig; -pub use normalize::spans::SpanAttribute; /// The config for store. #[derive(Serialize, Deserialize, Debug, Default)] @@ -56,6 +55,7 @@ pub struct StoreConfig { /// Emit breakdowns based on given configuration. pub breakdowns: Option, + /// Emit additional span attributes based on given configuration. pub span_attributes: BTreeSet, } diff --git a/relay-general/src/store/normalize/spans.rs b/relay-general/src/store/normalize/spans.rs index 70d0491c96..a3b34009a5 100644 --- a/relay-general/src/store/normalize/spans.rs +++ b/relay-general/src/store/normalize/spans.rs @@ -1,20 +1,9 @@ use std::collections::BTreeSet; use std::collections::HashMap; -use serde::{Deserialize, Serialize}; - use crate::protocol::{Event, Span, Timestamp}; use crate::types::Annotated; - -#[derive(Clone, Copy, Debug, Eq, PartialEq, PartialOrd, Ord, Hash, Serialize, Deserialize)] -pub enum SpanAttribute { - #[serde(rename = "exclusive-time")] - ExclusiveTime, - - /// forward compatibility - #[serde(other)] - Unknown, -} +use crate::types::SpanAttribute; #[derive(Clone, Debug)] struct TimeInterval { @@ -138,61 +127,68 @@ fn get_span_interval(span: &Span) -> Option { } pub fn normalize_spans(event: &mut Event, attributes: &BTreeSet) { - if attributes.contains(&SpanAttribute::ExclusiveTime) { - let spans = event.spans.value_mut().get_or_insert_with(|| Vec::new()); - - let mut span_map = HashMap::new(); - - for span in spans.iter() { - let span = match span.value() { - None => continue, - Some(span) => span, - }; - - let parent_span_id = match span.parent_span_id.value() { - None => continue, - Some(parent_span_id) => parent_span_id.clone(), - }; - - let interval = match get_span_interval(span) { - None => continue, - Some(interval) => interval, - }; - - span_map - .entry(parent_span_id) - .or_insert_with(Vec::new) - .push(interval) + for attribute in attributes { + match attribute { + SpanAttribute::ExclusiveTime => compute_span_exclusive_time(event), + SpanAttribute::Unknown => (), // ignored } + } +} - for span in spans.iter_mut() { - let mut span = match span.value_mut() { - None => continue, - Some(span) => span, - }; - - let span_id = match span.span_id.value() { - None => continue, - Some(span_id) => span_id, - }; - - let span_interval = match get_span_interval(span) { - None => continue, - Some(interval) => interval, - }; - - let child_intervals = match span_map.get_mut(span_id) { - Some(intervals) => { - // Make sure that the intervals are sorted by start time. - intervals.sort_unstable_by_key(|interval| interval.start); - merge_non_overlapping_intervals(intervals) - } - None => Vec::new(), - }; - - let exclusive_time = interval_exclusive_time(&span_interval, &child_intervals); - span.exclusive_time = Annotated::new(exclusive_time); - } +fn compute_span_exclusive_time(event: &mut Event) { + let spans = event.spans.value_mut().get_or_insert_with(|| Vec::new()); + + let mut span_map = HashMap::new(); + + for span in spans.iter() { + let span = match span.value() { + None => continue, + Some(span) => span, + }; + + let parent_span_id = match span.parent_span_id.value() { + None => continue, + Some(parent_span_id) => parent_span_id.clone(), + }; + + let interval = match get_span_interval(span) { + None => continue, + Some(interval) => interval, + }; + + span_map + .entry(parent_span_id) + .or_insert_with(Vec::new) + .push(interval) + } + + for span in spans.iter_mut() { + let mut span = match span.value_mut() { + None => continue, + Some(span) => span, + }; + + let span_id = match span.span_id.value() { + None => continue, + Some(span_id) => span_id, + }; + + let span_interval = match get_span_interval(span) { + None => continue, + Some(interval) => interval, + }; + + let child_intervals = match span_map.get_mut(span_id) { + Some(intervals) => { + // Make sure that the intervals are sorted by start time. + intervals.sort_unstable_by_key(|interval| interval.start); + merge_non_overlapping_intervals(intervals) + } + None => Vec::new(), + }; + + let exclusive_time = interval_exclusive_time(&span_interval, &child_intervals); + span.exclusive_time = Annotated::new(exclusive_time); } } diff --git a/relay-general/src/types/mod.rs b/relay-general/src/types/mod.rs index 29bc258c1a..9ad2814b02 100644 --- a/relay-general/src/types/mod.rs +++ b/relay-general/src/types/mod.rs @@ -7,6 +7,7 @@ mod annotated; mod impls; mod meta; +mod span_attributes; mod traits; mod value; @@ -15,5 +16,6 @@ pub use self::annotated::{ }; pub use self::impls::SerializePayload; pub use self::meta::{Error, ErrorKind, Meta, Range, Remark, RemarkType}; +pub use self::span_attributes::SpanAttribute; pub use self::traits::{Empty, FromValue, IntoValue, SkipSerialization}; pub use self::value::{to_value, Array, Map, Object, Value, ValueDescription}; diff --git a/relay-general/src/types/span_attributes.rs b/relay-general/src/types/span_attributes.rs new file mode 100644 index 0000000000..2d2d166191 --- /dev/null +++ b/relay-general/src/types/span_attributes.rs @@ -0,0 +1,12 @@ +use serde::{Deserialize, Serialize}; + +/// The span attribute to be computed. +#[derive(Clone, Copy, Debug, Eq, PartialEq, PartialOrd, Ord, Hash, Serialize, Deserialize)] +#[serde(rename_all = "kebab-case")] +pub enum SpanAttribute { + ExclusiveTime, + + /// forward compatibility + #[serde(other)] + Unknown, +} diff --git a/relay-server/src/actors/project.rs b/relay-server/src/actors/project.rs index 632384c49c..b3937b1f6f 100644 --- a/relay-server/src/actors/project.rs +++ b/relay-server/src/actors/project.rs @@ -15,7 +15,8 @@ use relay_common::{metric, ProjectId, ProjectKey}; use relay_config::Config; use relay_filter::{matches_any_origin, FiltersConfig}; use relay_general::pii::{DataScrubbingConfig, PiiConfig}; -use relay_general::store::{BreakdownsConfig, SpanAttribute}; +use relay_general::store::BreakdownsConfig; +use relay_general::types::SpanAttribute; use relay_metrics::{self, Aggregator, Bucket, Metric}; use relay_quotas::{Quota, RateLimits, Scoping}; use relay_sampling::SamplingConfig; From ccf8f9a0764fc9a6d580b1e4a00379f6ce5f3f66 Mon Sep 17 00:00:00 2001 From: Tony Xiao Date: Mon, 30 Aug 2021 11:47:04 -0400 Subject: [PATCH 6/9] make span mod non pub --- relay-general/src/store/normalize.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/relay-general/src/store/normalize.rs b/relay-general/src/store/normalize.rs index 75d10b0a42..f624be7828 100644 --- a/relay-general/src/store/normalize.rs +++ b/relay-general/src/store/normalize.rs @@ -26,7 +26,7 @@ mod contexts; mod logentry; mod mechanism; mod request; -pub mod spans; +mod spans; mod stacktrace; #[cfg(feature = "uaparser")] From 0a9462ce3b8a51cbde99a877db1dd95ec1e30bdc Mon Sep 17 00:00:00 2001 From: Tony Xiao Date: Tue, 31 Aug 2021 11:15:06 -0400 Subject: [PATCH 7/9] dedupe time span interval type --- .../src/store/normalize/breakdowns.rs | 10 +-- relay-general/src/store/normalize/spans.rs | 61 ++++++------------- 2 files changed, 25 insertions(+), 46 deletions(-) diff --git a/relay-general/src/store/normalize/breakdowns.rs b/relay-general/src/store/normalize/breakdowns.rs index ef43d11d7f..986b492d34 100644 --- a/relay-general/src/store/normalize/breakdowns.rs +++ b/relay-general/src/store/normalize/breakdowns.rs @@ -11,13 +11,13 @@ use crate::protocol::{Breakdowns, Event, Measurement, Measurements, Timestamp}; use crate::types::Annotated; #[derive(Clone, Debug)] -struct TimeWindowSpan { - start_timestamp: Timestamp, - end_timestamp: Timestamp, +pub struct TimeWindowSpan { + pub start_timestamp: Timestamp, + pub end_timestamp: Timestamp, } impl TimeWindowSpan { - fn new(start_timestamp: Timestamp, end_timestamp: Timestamp) -> Self { + pub fn new(start_timestamp: Timestamp, end_timestamp: Timestamp) -> Self { if end_timestamp < start_timestamp { return TimeWindowSpan { start_timestamp: end_timestamp, @@ -31,7 +31,7 @@ impl TimeWindowSpan { } } - fn get_duration(&self) -> f64 { + pub fn get_duration(&self) -> f64 { let delta: f64 = (self.end_timestamp.timestamp_nanos() - self.start_timestamp.timestamp_nanos()) as f64; // convert to milliseconds (1 ms = 1,000,000 nanoseconds) diff --git a/relay-general/src/store/normalize/spans.rs b/relay-general/src/store/normalize/spans.rs index a3b34009a5..249a141489 100644 --- a/relay-general/src/store/normalize/spans.rs +++ b/relay-general/src/store/normalize/spans.rs @@ -1,38 +1,15 @@ use std::collections::BTreeSet; use std::collections::HashMap; -use crate::protocol::{Event, Span, Timestamp}; +use crate::protocol::{Event, Span}; use crate::types::Annotated; use crate::types::SpanAttribute; -#[derive(Clone, Debug)] -struct TimeInterval { - start: Timestamp, - end: Timestamp, -} - -impl TimeInterval { - fn new(start: Timestamp, end: Timestamp) -> Self { - if end < start { - TimeInterval { - start: end, - end: start, - } - } else { - TimeInterval { start, end } - } - } - - fn get_duration(&self) -> f64 { - let delta: f64 = (self.end.timestamp_nanos() - self.start.timestamp_nanos()) as f64; - // convert to milliseconds (1 ms = 1,000,000 nanoseconds) - (delta / 1_000_000.00).abs() - } -} +use crate::store::normalize::breakdowns::TimeWindowSpan; /// Merge a list of intervals into a list of non overlapping intervals. /// Assumes that the input intervals are sorted by start time. -fn merge_non_overlapping_intervals(intervals: &mut [TimeInterval]) -> Vec { +fn merge_non_overlapping_intervals(intervals: &mut [TimeWindowSpan]) -> Vec { let mut non_overlapping_intervals = Vec::new(); // Make sure that there is at least 1 interval present. @@ -44,14 +21,14 @@ fn merge_non_overlapping_intervals(intervals: &mut [TimeInterval]) -> Vec Vec f64 { +fn interval_exclusive_time(source: &TimeWindowSpan, intervals: &[TimeWindowSpan]) -> f64 { let mut exclusive_time = 0.0; let mut remaining = source.clone(); for interval in intervals { - if interval.end < remaining.start { + if interval.end_timestamp < remaining.start_timestamp { // The interval is entirely to the left of the remaining interval, // so nothing to be done here. continue; - } else if interval.start >= remaining.end { + } else if interval.start_timestamp >= remaining.end_timestamp { // The interval is entirely to the right of the remaining interval, // so nothing to be done here. // @@ -90,25 +67,27 @@ fn interval_exclusive_time(source: &TimeInterval, intervals: &[TimeInterval]) -> } else { // The interval must intersect with the remaining interval in some way. - if interval.start > remaining.start { + if interval.start_timestamp > remaining.start_timestamp { // The interval begins within the remaining interval, there is a // portion to its left that should be added to the results. - exclusive_time += TimeInterval::new(remaining.start, interval.start).get_duration(); + exclusive_time += + TimeWindowSpan::new(remaining.start_timestamp, interval.start_timestamp) + .get_duration(); } - if interval.end < remaining.end { + if interval.end_timestamp < remaining.end_timestamp { // The interval ends within the remaining interval, so the // tail of the interval interesects with the head of the remaining // interval. // // Subtract the intersection by shifting the start of the remaining // interval. - remaining.start = interval.end; + remaining.start_timestamp = interval.end_timestamp; } else { // The interval ends to the right of the remaining interval, so // the interval intersects with the entirety of the remaining // interval. So zero out the interval. - remaining.start = remaining.end; + remaining.start_timestamp = remaining.end_timestamp; // There is nothing remaining to be checked. break; @@ -120,10 +99,10 @@ fn interval_exclusive_time(source: &TimeInterval, intervals: &[TimeInterval]) -> exclusive_time + remaining.get_duration() } -fn get_span_interval(span: &Span) -> Option { +fn get_span_interval(span: &Span) -> Option { let start_timestamp = *span.start_timestamp.value()?; let end_timestamp = *span.timestamp.value()?; - Some(TimeInterval::new(start_timestamp, end_timestamp)) + Some(TimeWindowSpan::new(start_timestamp, end_timestamp)) } pub fn normalize_spans(event: &mut Event, attributes: &BTreeSet) { @@ -181,7 +160,7 @@ fn compute_span_exclusive_time(event: &mut Event) { let child_intervals = match span_map.get_mut(span_id) { Some(intervals) => { // Make sure that the intervals are sorted by start time. - intervals.sort_unstable_by_key(|interval| interval.start); + intervals.sort_unstable_by_key(|interval| interval.start_timestamp); merge_non_overlapping_intervals(intervals) } None => Vec::new(), @@ -195,7 +174,7 @@ fn compute_span_exclusive_time(event: &mut Event) { #[cfg(test)] mod tests { use super::*; - use crate::protocol::{Event, EventType, Span, SpanId, TraceId}; + use crate::protocol::{Event, EventType, Span, SpanId, Timestamp, TraceId}; use chrono::{TimeZone, Utc}; fn make_span( From cd325daa6d37f4dcc8922554faf43d5bcb3f3a15 Mon Sep 17 00:00:00 2001 From: Tony Xiao Date: Tue, 31 Aug 2021 11:18:15 -0400 Subject: [PATCH 8/9] update changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 5527ffaef9..ae26404eba 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,7 @@ **Internal**: - Add new metrics on Relay's performance in dealing with buckets of metric aggregates, as well as the amount of aggregated buckets. ([#1070](https://github.com/getsentry/relay/pull/1070)) +- Add the exclusive time of a span. ([#1061](https://github.com/getsentry/relay/pull/1061)) ## 21.8.0 From 5dfc379d154124f75e93d22b2febf83f18ebd8b1 Mon Sep 17 00:00:00 2001 From: Tony Xiao Date: Wed, 1 Sep 2021 10:40:58 -0400 Subject: [PATCH 9/9] address PR comments --- .../src/store/normalize/breakdowns.rs | 55 +++++++++---------- relay-general/src/store/normalize/spans.rs | 40 +++++++------- 2 files changed, 44 insertions(+), 51 deletions(-) diff --git a/relay-general/src/store/normalize/breakdowns.rs b/relay-general/src/store/normalize/breakdowns.rs index 986b492d34..303a9d9678 100644 --- a/relay-general/src/store/normalize/breakdowns.rs +++ b/relay-general/src/store/normalize/breakdowns.rs @@ -12,28 +12,24 @@ use crate::types::Annotated; #[derive(Clone, Debug)] pub struct TimeWindowSpan { - pub start_timestamp: Timestamp, - pub end_timestamp: Timestamp, + pub start: Timestamp, + pub end: Timestamp, } impl TimeWindowSpan { - pub fn new(start_timestamp: Timestamp, end_timestamp: Timestamp) -> Self { - if end_timestamp < start_timestamp { + pub fn new(start: Timestamp, end: Timestamp) -> Self { + if end < start { return TimeWindowSpan { - start_timestamp: end_timestamp, - end_timestamp: start_timestamp, + start: end, + end: start, }; } - TimeWindowSpan { - start_timestamp, - end_timestamp, - } + TimeWindowSpan { start, end } } - pub fn get_duration(&self) -> f64 { - let delta: f64 = - (self.end_timestamp.timestamp_nanos() - self.start_timestamp.timestamp_nanos()) as f64; + pub fn duration(&self) -> f64 { + let delta: f64 = (self.end.timestamp_nanos() - self.start.timestamp_nanos()) as f64; // convert to milliseconds (1 ms = 1,000,000 nanoseconds) (delta / 1_000_000.00).abs() } @@ -50,8 +46,8 @@ fn get_op_time_spent(mut intervals: Vec) -> Option { return None; } - // sort by start_timestamp in ascending order - intervals.sort_unstable_by_key(|span| span.start_timestamp); + // sort by start timestamp in ascending order + intervals.sort_unstable_by_key(|span| span.start); let mut op_time_spent = 0.0; let mut previous_interval: Option = None; @@ -59,20 +55,19 @@ fn get_op_time_spent(mut intervals: Vec) -> Option { for current_interval in intervals.into_iter() { match previous_interval.as_mut() { Some(last_interval) => { - if last_interval.end_timestamp < current_interval.start_timestamp { + if last_interval.end < current_interval.start { // if current_interval does not overlap with last_interval, // then add last_interval to op_time_spent - op_time_spent += last_interval.get_duration(); + op_time_spent += last_interval.duration(); previous_interval = Some(current_interval); continue; } // current_interval and last_interval overlaps; so we merge these intervals - // invariant: last_interval.start_timestamp <= current_interval.start_timestamp + // invariant: last_interval.start <= current_interval.start - last_interval.end_timestamp = - std::cmp::max(last_interval.end_timestamp, current_interval.end_timestamp); + last_interval.end = std::cmp::max(last_interval.end, current_interval.end); } None => { previous_interval = Some(current_interval); @@ -81,7 +76,7 @@ fn get_op_time_spent(mut intervals: Vec) -> Option { } if let Some(remaining_interval) = previous_interval { - op_time_spent += remaining_interval.get_duration(); + op_time_spent += remaining_interval.duration(); } Some(op_time_spent) @@ -129,17 +124,17 @@ impl EmitBreakdowns for SpanOperationsConfig { Some(span_op) => span_op, }; - let start_timestamp = match span.start_timestamp.value() { + let start = match span.start_timestamp.value() { None => continue, - Some(start_timestamp) => start_timestamp, + Some(start) => start, }; - let end_timestamp = match span.timestamp.value() { + let end = match span.timestamp.value() { None => continue, - Some(end_timestamp) => end_timestamp, + Some(end) => end, }; - let cover = TimeWindowSpan::new(*start_timestamp, *end_timestamp); + let cover = TimeWindowSpan::new(*start, *end); // Only emit an operation breakdown measurement if the operation name matches any // entries in operation_name_breakdown. @@ -316,13 +311,13 @@ mod tests { #[test] fn test_emit_ops_breakdown() { fn make_span( - start_timestamp: Annotated, - end_timestamp: Annotated, + start: Annotated, + end: Annotated, op_name: String, ) -> Annotated { Annotated::new(Span { - timestamp: end_timestamp, - start_timestamp, + timestamp: end, + start_timestamp: start, description: Annotated::new("desc".to_owned()), op: Annotated::new(op_name), trace_id: Annotated::new(TraceId("4c79f60c11214eb38604f4ae0781bfb2".into())), diff --git a/relay-general/src/store/normalize/spans.rs b/relay-general/src/store/normalize/spans.rs index 249a141489..cdd91ab8c6 100644 --- a/relay-general/src/store/normalize/spans.rs +++ b/relay-general/src/store/normalize/spans.rs @@ -21,14 +21,14 @@ fn merge_non_overlapping_intervals(intervals: &mut [TimeWindowSpan]) -> Vec