From aba67faf77501b5601ace2a3ab5cffbfcf22b6d9 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Tue, 25 Jun 2024 19:58:38 -0400 Subject: [PATCH 1/6] fix(browser): Make sure measure spans have valid start timestamps --- .../metrics/pageload-measure-spans/subject.js | 5 ++ .../metrics/pageload-measure-spans/test.ts | 28 ++++++++ .../src/metrics/browserMetrics.ts | 66 +++++++++++-------- 3 files changed, 72 insertions(+), 27 deletions(-) create mode 100644 dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/subject.js create mode 100644 dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/test.ts diff --git a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/subject.js b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/subject.js new file mode 100644 index 000000000000..ae1ea46b65ef --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/subject.js @@ -0,0 +1,5 @@ +const end = performance.now(); +performance.measure('Next.js-before-hydration', { + duration: 10000, + end, +}); diff --git a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/test.ts b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/test.ts new file mode 100644 index 000000000000..51972dc6c499 --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/test.ts @@ -0,0 +1,28 @@ +import { expect } from '@playwright/test'; +import type { Event } from '@sentry/types'; + +import { sentryTest } from '../../../../utils/fixtures'; +import { getFirstSentryEnvelopeRequest, shouldSkipTracingTest } from '../../../../utils/helpers'; + +// Validation test for https://github.com/getsentry/sentry-javascript/issues/12281 +sentryTest('should add browser-related spans to pageload transaction', async ({ getLocalTestPath, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + + const url = await getLocalTestPath({ testDir: __dirname }); + + const eventData = await getFirstSentryEnvelopeRequest(page, url); + const browserSpans = eventData.spans?.filter(({ op }) => op === 'browser'); + + // Spans `domContentLoadedEvent`, `connect`, `cache` and `DNS` are not + // always inside `pageload` transaction. + expect(browserSpans?.length).toBeGreaterThanOrEqual(4); + + const requestSpan = browserSpans!.find(({ description }) => description === 'request'); + expect(requestSpan).toBeDefined(); + const measureSpan = browserSpans!.find(({ op }) => op === 'measure'); + expect(measureSpan).toBeDefined(); + + expect(requestSpan!.start_timestamp).toBeLessThanOrEqual(measureSpan!.start_timestamp); +}); diff --git a/packages/browser-utils/src/metrics/browserMetrics.ts b/packages/browser-utils/src/metrics/browserMetrics.ts index 6999641a641f..dbf3b87b84ed 100644 --- a/packages/browser-utils/src/metrics/browserMetrics.ts +++ b/packages/browser-utils/src/metrics/browserMetrics.ts @@ -342,15 +342,34 @@ export function _addMeasureSpans( duration: number, timeOrigin: number, ): number { - const measureStartTimestamp = timeOrigin + startTime; - const measureEndTimestamp = measureStartTimestamp + duration; + const navEntry = getNavigationEntry(); + const requestTime = msToSec(navEntry ? navEntry.requestStart : 0); + // Because performance.measure accepts arbtirary timestamps it can produce + // spans that happen before the browser even makes a request for the page. + // + // An example of this is the automatically generated Next.js-before-hydration + // spans created by the Next.js framework. + // + // To prevent this we will pin the start timestamp to the request start time + // This does make duration inaccruate, so if this does happen, we will add + // an attribute to the span + const measureStartTimestamp = timeOrigin + Math.max(startTime, requestTime); + const startTimeStamp = timeOrigin + startTime; + const measureEndTimestamp = startTimeStamp + duration; + + const attributes: SpanAttributes = { + [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: 'auto.resource.browser.metrics', + }; + + if (measureStartTimestamp !== startTimeStamp) { + attributes['sentry.browser.measure_happened_before_request'] = true; + attributes['sentry.browser.measure_start_time'] = measureStartTimestamp; + } startAndEndSpan(span, measureStartTimestamp, measureEndTimestamp, { name: entry.name as string, op: entry.entryType as string, - attributes: { - [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: 'auto.resource.browser.metrics', - }, + attributes, }); return measureStartTimestamp; @@ -395,36 +414,29 @@ function _addPerformanceNavigationTiming( /** Create request and response related spans */ // eslint-disable-next-line @typescript-eslint/no-explicit-any function _addRequest(span: Span, entry: Record, timeOrigin: number): void { + const requestStartTimestamp = timeOrigin + msToSec(entry.requestStart as number); + const responseEndTimestamp = timeOrigin + msToSec(entry.responseEnd as number); + const responseStartTimestamp = timeOrigin + msToSec(entry.responseStart as number); if (entry.responseEnd) { // It is possible that we are collecting these metrics when the page hasn't finished loading yet, for example when the HTML slowly streams in. // In this case, ie. when the document request hasn't finished yet, `entry.responseEnd` will be 0. // In order not to produce faulty spans, where the end timestamp is before the start timestamp, we will only collect // these spans when the responseEnd value is available. The backend (Relay) would drop the entire span if it contained faulty spans. - startAndEndSpan( - span, - timeOrigin + msToSec(entry.requestStart as number), - timeOrigin + msToSec(entry.responseEnd as number), - { - op: 'browser', - name: 'request', - attributes: { - [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: 'auto.ui.browser.metrics', - }, + startAndEndSpan(span, requestStartTimestamp, responseEndTimestamp, { + op: 'browser', + name: 'request', + attributes: { + [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: 'auto.ui.browser.metrics', }, - ); + }); - startAndEndSpan( - span, - timeOrigin + msToSec(entry.responseStart as number), - timeOrigin + msToSec(entry.responseEnd as number), - { - op: 'browser', - name: 'response', - attributes: { - [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: 'auto.ui.browser.metrics', - }, + startAndEndSpan(span, responseStartTimestamp, responseEndTimestamp, { + op: 'browser', + name: 'response', + attributes: { + [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: 'auto.ui.browser.metrics', }, - ); + }); } } From 89ea0113e447e7579a8ee35814caf58ecba99631 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Wed, 26 Jun 2024 12:25:06 -0400 Subject: [PATCH 2/6] Update packages/browser-utils/src/metrics/browserMetrics.ts Co-authored-by: Francesco Novy --- packages/browser-utils/src/metrics/browserMetrics.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/browser-utils/src/metrics/browserMetrics.ts b/packages/browser-utils/src/metrics/browserMetrics.ts index dbf3b87b84ed..4e473e42ea47 100644 --- a/packages/browser-utils/src/metrics/browserMetrics.ts +++ b/packages/browser-utils/src/metrics/browserMetrics.ts @@ -344,7 +344,7 @@ export function _addMeasureSpans( ): number { const navEntry = getNavigationEntry(); const requestTime = msToSec(navEntry ? navEntry.requestStart : 0); - // Because performance.measure accepts arbtirary timestamps it can produce + // Because performance.measure accepts arbitrary timestamps it can produce // spans that happen before the browser even makes a request for the page. // // An example of this is the automatically generated Next.js-before-hydration From 1965c2cc382d7fcd8c5bb6a355bea4bd4c9bac67 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Wed, 26 Jun 2024 12:43:57 -0400 Subject: [PATCH 3/6] test --- .../suites/tracing/metrics/pageload-measure-spans/test.ts | 2 ++ 1 file changed, 2 insertions(+) diff --git a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/test.ts b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/test.ts index 51972dc6c499..d6794fc63887 100644 --- a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/test.ts +++ b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/test.ts @@ -19,6 +19,8 @@ sentryTest('should add browser-related spans to pageload transaction', async ({ // always inside `pageload` transaction. expect(browserSpans?.length).toBeGreaterThanOrEqual(4); + expect(browserSpans).toEqual([]); + const requestSpan = browserSpans!.find(({ description }) => description === 'request'); expect(requestSpan).toBeDefined(); const measureSpan = browserSpans!.find(({ op }) => op === 'measure'); From 98b02806258c739b7d6135405bd060c4ba89f710 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Wed, 26 Jun 2024 12:44:29 -0400 Subject: [PATCH 4/6] this too --- .../suites/tracing/metrics/pageload-measure-spans/subject.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/subject.js b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/subject.js index ae1ea46b65ef..e4112132d56f 100644 --- a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/subject.js +++ b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/subject.js @@ -1,5 +1,5 @@ const end = performance.now(); performance.measure('Next.js-before-hydration', { - duration: 10000, + duration: 2000, end, }); From ef249b9c24ddf036e8f6bf628542911e1d0bf8a4 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Thu, 27 Jun 2024 13:57:48 -0400 Subject: [PATCH 5/6] move into template --- .../metrics/pageload-measure-spans/subject.js | 5 ----- .../metrics/pageload-measure-spans/template.html | 16 ++++++++++++++++ 2 files changed, 16 insertions(+), 5 deletions(-) delete mode 100644 dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/subject.js create mode 100644 dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/template.html diff --git a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/subject.js b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/subject.js deleted file mode 100644 index e4112132d56f..000000000000 --- a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/subject.js +++ /dev/null @@ -1,5 +0,0 @@ -const end = performance.now(); -performance.measure('Next.js-before-hydration', { - duration: 2000, - end, -}); diff --git a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/template.html b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/template.html new file mode 100644 index 000000000000..7d1e4f088fa6 --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/template.html @@ -0,0 +1,16 @@ + + + + + + + +
+ + From 045c4bb9b4ef8102ab0c2f31e2a44cf9b3ef5059 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Thu, 27 Jun 2024 15:42:12 -0400 Subject: [PATCH 6/6] assert on correct sets of spans --- .../metrics/pageload-measure-spans/init.js | 21 +++++++++++++++++++ .../pageload-measure-spans/template.html | 16 -------------- .../metrics/pageload-measure-spans/test.ts | 11 +++++++--- 3 files changed, 29 insertions(+), 19 deletions(-) create mode 100644 dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/init.js delete mode 100644 dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/template.html diff --git a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/init.js b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/init.js new file mode 100644 index 000000000000..d34167f7b256 --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/init.js @@ -0,0 +1,21 @@ +// Add measure before SDK initializes +const end = performance.now(); +performance.measure('Next.js-before-hydration', { + duration: 1000, + end, +}); + +import * as Sentry from '@sentry/browser'; + +window.Sentry = Sentry; + +Sentry.init({ + debug: true, + dsn: 'https://public@dsn.ingest.sentry.io/1337', + integrations: [ + Sentry.browserTracingIntegration({ + idleTimeout: 9000, + }), + ], + tracesSampleRate: 1, +}); diff --git a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/template.html b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/template.html deleted file mode 100644 index 7d1e4f088fa6..000000000000 --- a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/template.html +++ /dev/null @@ -1,16 +0,0 @@ - - - - - - - -
- - diff --git a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/test.ts b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/test.ts index d6794fc63887..9209e8ca5c32 100644 --- a/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/test.ts +++ b/dev-packages/browser-integration-tests/suites/tracing/metrics/pageload-measure-spans/test.ts @@ -19,12 +19,17 @@ sentryTest('should add browser-related spans to pageload transaction', async ({ // always inside `pageload` transaction. expect(browserSpans?.length).toBeGreaterThanOrEqual(4); - expect(browserSpans).toEqual([]); - const requestSpan = browserSpans!.find(({ description }) => description === 'request'); expect(requestSpan).toBeDefined(); - const measureSpan = browserSpans!.find(({ op }) => op === 'measure'); + + const measureSpan = eventData.spans?.find(({ op }) => op === 'measure'); expect(measureSpan).toBeDefined(); expect(requestSpan!.start_timestamp).toBeLessThanOrEqual(measureSpan!.start_timestamp); + expect(measureSpan?.data).toEqual({ + 'sentry.browser.measure_happened_before_request': true, + 'sentry.browser.measure_start_time': expect.any(Number), + 'sentry.op': 'measure', + 'sentry.origin': 'auto.resource.browser.metrics', + }); });