From 26728d4469c48416dafb68a09e66f66e78a78064 Mon Sep 17 00:00:00 2001 From: Luca Forstner Date: Tue, 16 Jan 2024 16:34:03 +0000 Subject: [PATCH 1/3] fix(tracing-internal): Only collect request/response spans when browser performance timing is available --- .../src/browser/metrics/index.ts | 34 +++++++++++-------- 1 file changed, 20 insertions(+), 14 deletions(-) diff --git a/packages/tracing-internal/src/browser/metrics/index.ts b/packages/tracing-internal/src/browser/metrics/index.ts index 36aa0c3659d9..5fa4e754cd96 100644 --- a/packages/tracing-internal/src/browser/metrics/index.ts +++ b/packages/tracing-internal/src/browser/metrics/index.ts @@ -369,21 +369,27 @@ function _addPerformanceNavigationTiming( /** Create request and response related spans */ // eslint-disable-next-line @typescript-eslint/no-explicit-any function _addRequest(transaction: Transaction, entry: Record, timeOrigin: number): void { - _startChild(transaction, { - op: 'browser', - origin: 'auto.browser.browser.metrics', - description: 'request', - startTimestamp: timeOrigin + msToSec(entry.requestStart as number), - endTimestamp: timeOrigin + msToSec(entry.responseEnd as number), - }); + // 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. Relay would drop the entire transaction if it contained faulty spans. + if (entry.responseEnd !== 0) { + _startChild(transaction, { + op: 'browser', + origin: 'auto.browser.browser.metrics', + description: 'request', + startTimestamp: timeOrigin + msToSec(entry.requestStart as number), + endTimestamp: timeOrigin + msToSec(entry.responseEnd as number), + }); - _startChild(transaction, { - op: 'browser', - origin: 'auto.browser.browser.metrics', - description: 'response', - startTimestamp: timeOrigin + msToSec(entry.responseStart as number), - endTimestamp: timeOrigin + msToSec(entry.responseEnd as number), - }); + _startChild(transaction, { + op: 'browser', + origin: 'auto.browser.browser.metrics', + description: 'response', + startTimestamp: timeOrigin + msToSec(entry.responseStart as number), + endTimestamp: timeOrigin + msToSec(entry.responseEnd as number), + }); + } } export interface ResourceEntry extends Record { From efed3ddace4d7ae6c71e93c5f86fe81007c2ee62 Mon Sep 17 00:00:00 2001 From: Luca Forstner Date: Wed, 17 Jan 2024 09:32:43 +0000 Subject: [PATCH 2/3] Add test --- .../app/very-slow-component/page.tsx | 6 ++++++ .../nextjs-app-dir/tests/transactions.test.ts | 17 +++++++++++++++++ 2 files changed, 23 insertions(+) create mode 100644 dev-packages/e2e-tests/test-applications/nextjs-app-dir/app/very-slow-component/page.tsx diff --git a/dev-packages/e2e-tests/test-applications/nextjs-app-dir/app/very-slow-component/page.tsx b/dev-packages/e2e-tests/test-applications/nextjs-app-dir/app/very-slow-component/page.tsx new file mode 100644 index 000000000000..ab40d1e62d5f --- /dev/null +++ b/dev-packages/e2e-tests/test-applications/nextjs-app-dir/app/very-slow-component/page.tsx @@ -0,0 +1,6 @@ +export const dynamic = 'force-dynamic'; + +export default async function SuperSlowPage() { + await new Promise(resolve => setTimeout(resolve, 10000)); + return null; +} diff --git a/dev-packages/e2e-tests/test-applications/nextjs-app-dir/tests/transactions.test.ts b/dev-packages/e2e-tests/test-applications/nextjs-app-dir/tests/transactions.test.ts index f975ec49e606..3532c5c64746 100644 --- a/dev-packages/e2e-tests/test-applications/nextjs-app-dir/tests/transactions.test.ts +++ b/dev-packages/e2e-tests/test-applications/nextjs-app-dir/tests/transactions.test.ts @@ -139,3 +139,20 @@ test('Should send a transaction for instrumented server actions', async ({ page expect(Object.keys((await serverComponentTransactionPromise).request?.headers || {}).length).toBeGreaterThan(0); }); + +test('Will not include spans in pageload transaction with faulty timestamps for slow loading pages', async ({ + page, +}) => { + const pageloadTransactionEventPromise = waitForTransaction('nextjs-13-app-dir', transactionEvent => { + return ( + transactionEvent?.contexts?.trace?.op === 'pageload' && transactionEvent?.transaction === '/very-slow-component' + ); + }); + + await page.goto('/very-slow-component'); + + const pageLoadTransaction = await pageloadTransactionEventPromise; + + // @ts-expect-error We are looking at the serialized span format here + expect(pageLoadTransaction.spans?.filter(span => span.timestamp < span.start_timestamp)).toHaveLength(0); +}); From c8742e5bc2d0bac93ef37d78792e46462654d20a Mon Sep 17 00:00:00 2001 From: Luca Forstner Date: Wed, 17 Jan 2024 09:36:29 +0000 Subject: [PATCH 3/3] Review feedback --- packages/tracing-internal/src/browser/metrics/index.ts | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/packages/tracing-internal/src/browser/metrics/index.ts b/packages/tracing-internal/src/browser/metrics/index.ts index 5fa4e754cd96..2d3ae00db7ae 100644 --- a/packages/tracing-internal/src/browser/metrics/index.ts +++ b/packages/tracing-internal/src/browser/metrics/index.ts @@ -369,11 +369,11 @@ function _addPerformanceNavigationTiming( /** Create request and response related spans */ // eslint-disable-next-line @typescript-eslint/no-explicit-any function _addRequest(transaction: Transaction, entry: Record, timeOrigin: number): void { - // 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. Relay would drop the entire transaction if it contained faulty spans. - if (entry.responseEnd !== 0) { + 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 transaction if it contained faulty spans. _startChild(transaction, { op: 'browser', origin: 'auto.browser.browser.metrics',