Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 4 commits into from
Oct 30, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 4 additions & 8 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
@@ -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

Expand All @@ -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))
Expand Down
4 changes: 3 additions & 1 deletion relay-dynamic-config/src/defaults.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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}"),
Expand Down
133 changes: 130 additions & 3 deletions relay-event-normalization/src/normalize/span/tag_extraction.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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};
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -77,6 +81,8 @@ impl SpanTagKey {
SpanTagKey::SpanOp => "op",
SpanTagKey::StatusCode => "status_code",
SpanTagKey::System => "system",
SpanTagKey::TimeToFullDisplay => "ttfd",
SpanTagKey::TimeToInitialDisplay => "ttid",
}
}
}
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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.
///
Expand Down Expand Up @@ -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);
}
}
}
71 changes: 56 additions & 15 deletions relay-server/src/metrics_extraction/event.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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"));
}
}
}