feat(spans): Add TTID and TTFD tags (#2662)

If `ui.load.initial_display` and/or `ui.load.full_display` spans are present, mark spans happening before those with `ttid` and `ttfd` tags.
getsentry · Oct 30, 2023 · 219676e · 219676e
1 parent ee3036c
commit 219676e
Show file tree

Hide file tree

Showing 4 changed files with 193 additions and 27 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -1,22 +1,19 @@
 # Changelog
 
-## Unrelease
+## Unreleased
 
 **Features**:
 
 - Add inbound filters option to filter legacy Edge browsers (i.e. versions 12-18 ) ([#2650](https://github.com/getsentry/relay/pull/2650))
 - Group resource spans by scrubbed domain and filename. ([#2654](https://github.com/getsentry/relay/pull/2654))
+- Filter outliers (>180s) for mobile measurements. ([#2649](https://github.com/getsentry/relay/pull/2649))
+- Allow access to more context fields in dynamic sampling and metric extraction. ([#2607](https://github.com/getsentry/relay/pull/2607), [#2640](https://github.com/getsentry/relay/pull/2640))
 
 **Internal**:
 
 - Disable resource link span ingestion. ([#2647](https://github.com/getsentry/relay/pull/2647))
 - Collect `http.decoded_response_content_length`. ([#2638](https://github.com/getsentry/relay/pull/2638))
-
-
-**Features**:
-
-- Filter outliers (>180s) for mobile measurements. ([#2649](https://github.com/getsentry/relay/pull/2649))
-- Allow access to more context fields in dynamic sampling and metric extraction. ([#2607](https://github.com/getsentry/relay/pull/2607), [#2640](https://github.com/getsentry/relay/pull/2640))
+- Add TTID and TTFD tags to mobile spans. ([#2662](https://github.com/getsentry/relay/pull/2662))
 
 ## 23.10.1
 
@@ -26,7 +23,6 @@
 - Remove event spans starting or ending before January 1, 1970 UTC. ([#2627](https://github.com/getsentry/relay/pull/2627))
 - Remove event breadcrumbs dating before January 1, 1970 UTC. ([#2635](https://github.com/getsentry/relay/pull/2635))
 
-
 **Internal**:
 
 - Report global config fetch errors after interval of constant failures elapsed. ([#2628](https://github.com/getsentry/relay/pull/2628))

diff --git a/relay-dynamic-config/src/defaults.rs b/relay-dynamic-config/src/defaults.rs
@@ -145,7 +145,9 @@ pub fn add_span_metrics(project_config: &mut ProjectConfig) {
                 ("span.", "system"),
                 ("", "transaction.method"),
                 ("", "transaction.op"),
-                ("", "resource.render_blocking_status"), // only set for resource spans.
+                ("", "resource.render_blocking_status"), // only set for resource spans
+                ("", "ttid"),                            // only set for mobile spans
+                ("", "ttfd"),                            // only set for mobile spans
             ]
             .map(|(prefix, key)| TagSpec {
                 key: format!("{prefix}{key}"),

diff --git a/relay-event-normalization/src/normalize/span/tag_extraction.rs b/relay-event-normalization/src/normalize/span/tag_extraction.rs
@@ -6,7 +6,7 @@ use std::ops::ControlFlow;
 
 use once_cell::sync::Lazy;
 use regex::Regex;
-use relay_event_schema::protocol::{Event, Span, TraceContext};
+use relay_event_schema::protocol::{Event, Span, Timestamp, TraceContext};
 use relay_protocol::Annotated;
 use sqlparser::ast::Visit;
 use sqlparser::ast::{ObjectName, Visitor};
@@ -47,6 +47,10 @@ pub enum SpanTagKey {
     SpanOp,
     StatusCode,
     System,
+    /// Contributes to Time-To-Initial-Display.
+    TimeToInitialDisplay,
+    /// Contributes to Time-To-Full-Display.
+    TimeToFullDisplay,
 }
 
 impl SpanTagKey {
@@ -77,6 +81,8 @@ impl SpanTagKey {
             SpanTagKey::SpanOp => "op",
             SpanTagKey::StatusCode => "status_code",
             SpanTagKey::System => "system",
+            SpanTagKey::TimeToFullDisplay => "ttfd",
+            SpanTagKey::TimeToInitialDisplay => "ttid",
         }
     }
 }
@@ -127,12 +133,15 @@ pub(crate) fn extract_span_tags(event: &mut Event, config: &Config) {
         return;
     };
 
+    let ttid = timestamp_by_op(spans, "ui.load.initial_display");
+    let ttfd = timestamp_by_op(spans, "ui.load.full_display");
+
     for span in spans {
         let Some(span) = span.value_mut().as_mut() else {
             continue;
         };
 
-        let tags = extract_tags(span, config);
+        let tags = extract_tags(span, config, ttid, ttfd);
 
         span.sentry_tags = Annotated::new(
             shared_tags
@@ -207,7 +216,12 @@ pub fn extract_shared_tags(event: &Event) -> BTreeMap<SpanTagKey, String> {
 /// [span operations](https://develop.sentry.dev/sdk/performance/span-operations/) and
 /// existing [span data](https://develop.sentry.dev/sdk/performance/span-data-conventions/) fields,
 /// and rely on Sentry conventions and heuristics.
-pub(crate) fn extract_tags(span: &Span, config: &Config) -> BTreeMap<SpanTagKey, String> {
+pub(crate) fn extract_tags(
+    span: &Span,
+    config: &Config,
+    initial_display: Option<Timestamp>,
+    full_display: Option<Timestamp>,
+) -> BTreeMap<SpanTagKey, String> {
     let mut span_tags: BTreeMap<SpanTagKey, String> = BTreeMap::new();
 
     let system = span
@@ -376,9 +390,33 @@ pub(crate) fn extract_tags(span: &Span, config: &Config) -> BTreeMap<SpanTagKey,
         span_tags.insert(SpanTagKey::StatusCode, status_code);
     }
 
+    if let Some(end_time) = span.timestamp.value() {
+        if let Some(initial_display) = initial_display {
+            if end_time <= &initial_display {
+                span_tags.insert(SpanTagKey::TimeToInitialDisplay, "ttid".to_owned());
+            }
+        }
+        if let Some(full_display) = full_display {
+            if end_time <= &full_display {
+                span_tags.insert(SpanTagKey::TimeToFullDisplay, "ttfd".to_owned());
+            }
+        }
+    }
+
     span_tags
 }
 
+/// Finds first matching span and get its timestamp.
+///
+/// Used to get time-to-initial/full-display times.
+fn timestamp_by_op(spans: &[Annotated<Span>], op: &str) -> Option<Timestamp> {
+    spans
+        .iter()
+        .filter_map(Annotated::value)
+        .find(|span| span.op.as_str() == Some(op))
+        .and_then(|span| span.timestamp.value().copied())
+}
+
 /// Trims the given string with the given maximum bytes. Splitting only happens
 /// on char boundaries.
 ///
@@ -772,4 +810,93 @@ LIMIT 1
             assert_eq!(sql_action_from_query(query).unwrap(), expected)
         }
     }
+
+    #[test]
+    fn test_display_times() {
+        let json = r#"
+            {
+                "type": "transaction",
+                "platform": "javascript",
+                "start_timestamp": "2021-04-26T07:59:01+0100",
+                "timestamp": "2021-04-26T08:00:00+0100",
+                "transaction": "foo",
+                "contexts": {
+                    "trace": {
+                        "trace_id": "ff62a8b040f340bda5d830223def1d81",
+                        "span_id": "bd429c44b67a3eb4"
+                    }
+                },
+                "spans": [
+                    {
+                        "op": "before_first_display",
+                        "span_id": "bd429c44b67a3eb1",
+                        "start_timestamp": 1597976300.0000000,
+                        "timestamp": 1597976302.0000000,
+                        "trace_id": "ff62a8b040f340bda5d830223def1d81"
+                    },
+                    {
+                        "op": "ui.load.initial_display",
+                        "span_id": "bd429c44b67a3eb2",
+                        "start_timestamp": 1597976300.0000000,
+                        "timestamp": 1597976303.0000000,
+                        "trace_id": "ff62a8b040f340bda5d830223def1d81"
+                    },
+                    {
+                        "span_id": "bd429c44b67a3eb2",
+                        "start_timestamp": 1597976303.0000000,
+                        "timestamp": 1597976305.0000000,
+                        "trace_id": "ff62a8b040f340bda5d830223def1d81"
+                    },
+                    {
+                        "op": "ui.load.full_display",
+                        "span_id": "bd429c44b67a3eb2",
+                        "start_timestamp": 1597976304.0000000,
+                        "timestamp": 1597976306.0000000,
+                        "trace_id": "ff62a8b040f340bda5d830223def1d81"
+                    },
+                    {
+                        "op": "after_full_display",
+                        "span_id": "bd429c44b67a3eb2",
+                        "start_timestamp": 1597976307.0000000,
+                        "timestamp": 1597976308.0000000,
+                        "trace_id": "ff62a8b040f340bda5d830223def1d81"
+                    }
+                ]
+            }
+        "#;
+
+        let mut event = Annotated::<Event>::from_json(json)
+            .unwrap()
+            .into_value()
+            .unwrap();
+
+        extract_span_tags(
+            &mut event,
+            &Config {
+                max_tag_value_size: 200,
+            },
+        );
+
+        let spans = event.spans.value().unwrap();
+
+        // First two spans contribute to initial display & full display:
+        for span in &spans[..2] {
+            let tags = span.value().unwrap().sentry_tags.value().unwrap();
+            assert_eq!(tags.get("ttid").unwrap().as_str(), Some("ttid"));
+            assert_eq!(tags.get("ttfd").unwrap().as_str(), Some("ttfd"));
+        }
+
+        // First four spans contribute to full display:
+        for span in &spans[2..4] {
+            let tags = span.value().unwrap().sentry_tags.value().unwrap();
+            assert_eq!(tags.get("ttid"), None);
+            assert_eq!(tags.get("ttfd").unwrap().as_str(), Some("ttfd"));
+        }
+
+        for span in &spans[4..] {
+            let tags = span.value().unwrap().sentry_tags.value().unwrap();
+            assert_eq!(tags.get("ttid"), None);
+            assert_eq!(tags.get("ttfd"), None);
+        }
+    }
 }
diff --git a/relay-server/src/metrics_extraction/event.rs b/relay-server/src/metrics_extraction/event.rs
@@ -1086,70 +1086,111 @@ mod tests {
     }
 
     /// Helper function for span metric extraction tests.
-    fn extract_span_metrics(span_op: &str, duration_millis: f64) -> Vec<Bucket> {
+    fn extract_span_metrics(span: &Span) -> Vec<Bucket> {
+        let mut config = ProjectConfig::default();
+        config.features.0.insert(Feature::SpanMetricsExtraction);
+        config.sanitize(); // apply defaults for span extraction
+
+        let extraction_config = config.metric_extraction.ok().unwrap();
+        generic::extract_metrics(span, &extraction_config)
+    }
+
+    /// Helper function for span metric extraction tests.
+    fn extract_span_metrics_op_duration(span_op: &str, duration_millis: f64) -> Vec<Bucket> {
         let mut span = Span::default();
         span.timestamp
             .set_value(Some(Timestamp::from(DateTime::<Utc>::MAX_UTC))); // whatever
         span.op.set_value(Some(span_op.into()));
         span.exclusive_time.set_value(Some(duration_millis));
 
-        let mut config = ProjectConfig::default();
-        config.features.0.insert(Feature::SpanMetricsExtraction);
-        config.sanitize(); // apply defaults for span extraction
-
-        let extraction_config = config.metric_extraction.ok().unwrap();
-        generic::extract_metrics(&span, &extraction_config)
+        extract_span_metrics(&span)
     }
 
     #[test]
     fn test_app_start_cold_inlier() {
-        assert_eq!(2, extract_span_metrics("app.start.cold", 180000.0).len());
+        assert_eq!(
+            2,
+            extract_span_metrics_op_duration("app.start.cold", 180000.0).len()
+        );
     }
 
     #[test]
     fn test_app_start_cold_outlier() {
-        assert_eq!(0, extract_span_metrics("app.start.cold", 181000.0).len());
+        assert_eq!(
+            0,
+            extract_span_metrics_op_duration("app.start.cold", 181000.0).len()
+        );
     }
 
     #[test]
     fn test_app_start_warm_inlier() {
-        assert_eq!(2, extract_span_metrics("app.start.warm", 180000.0).len());
+        assert_eq!(
+            2,
+            extract_span_metrics_op_duration("app.start.warm", 180000.0).len()
+        );
     }
 
     #[test]
     fn test_app_start_warm_outlier() {
-        assert_eq!(0, extract_span_metrics("app.start.warm", 181000.0).len());
+        assert_eq!(
+            0,
+            extract_span_metrics_op_duration("app.start.warm", 181000.0).len()
+        );
     }
 
     #[test]
     fn test_ui_load_initial_display_inlier() {
         assert_eq!(
             2,
-            extract_span_metrics("ui.load.initial_display", 180000.0).len()
+            extract_span_metrics_op_duration("ui.load.initial_display", 180000.0).len()
         );
     }
 
     #[test]
     fn test_ui_load_initial_display_outlier() {
         assert_eq!(
             0,
-            extract_span_metrics("ui.load.initial_display", 181000.0).len()
+            extract_span_metrics_op_duration("ui.load.initial_display", 181000.0).len()
         );
     }
 
     #[test]
     fn test_ui_load_full_display_inlier() {
         assert_eq!(
             2,
-            extract_span_metrics("ui.load.full_display", 180000.0).len()
+            extract_span_metrics_op_duration("ui.load.full_display", 180000.0).len()
         );
     }
 
     #[test]
     fn test_ui_load_full_display_outlier() {
         assert_eq!(
             0,
-            extract_span_metrics("ui.load.full_display", 181000.0).len()
+            extract_span_metrics_op_duration("ui.load.full_display", 181000.0).len()
         );
     }
+
+    #[test]
+    fn test_display_times_extracted() {
+        let span = r#"{
+            "op": "http.client",
+            "span_id": "bd429c44b67a3eb4",
+            "start_timestamp": 1597976300.0000000,
+            "timestamp": 1597976302.0000000,
+            "exclusive_time": 100,
+            "trace_id": "ff62a8b040f340bda5d830223def1d81",
+            "sentry_tags": {
+                "ttid": "ttid",
+                "ttfd": "ttfd"
+            }
+        }"#;
+        let span = Annotated::from_json(span).unwrap().into_value().unwrap();
+        let metrics = extract_span_metrics(&span);
+
+        assert!(!metrics.is_empty());
+        for metric in metrics {
+            assert_eq!(metric.tag("ttid"), Some("ttid"));
+            assert_eq!(metric.tag("ttfd"), Some("ttfd"));
+        }
+    }
 }