diff --git a/packages/browser-utils/src/performance/entries.ts b/packages/browser-utils/src/performance/entries.ts index f28e60f1cb3e..79eae716418d 100644 --- a/packages/browser-utils/src/performance/entries.ts +++ b/packages/browser-utils/src/performance/entries.ts @@ -5,6 +5,7 @@ import { browserPerformanceTimeOrigin, getActiveSpan, parseUrl, + performanceTimeToSeconds, RESOURCE_SPAN_NAME_FALLBACK, SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN, setMeasurement, @@ -108,7 +109,7 @@ export function startTrackingLongTasks(): void { const { attributes: parentAttributes, start_timestamp: parentStartTimestamp } = spanToJSON(parent); for (const entry of entries) { - const startTime = msToSec((browserPerformanceTimeOrigin() as number) + entry.startTime); + const startTime = performanceTimeToSeconds(entry.startTime) as number; const duration = msToSec(entry.duration); if (parentAttributes[SENTRY_OP] === 'navigation' && parentStartTimestamp && startTime < parentStartTimestamp) { @@ -147,7 +148,7 @@ export function startTrackingLongAnimationFrames(): void { continue; } - const startTime = msToSec((browserPerformanceTimeOrigin() as number) + entry.startTime); + const startTime = performanceTimeToSeconds(entry.startTime) as number; const { start_timestamp: parentStartTimestamp, @@ -217,13 +218,14 @@ export function addPerformanceEntries(span: Span, options: AddPerformanceEntries const { spanStreamingEnabled, ignoreResourceSpans } = options; - const timeOrigin = msToSec(origin); - const performanceEntries = performance.getEntries(); const { attributes, start_timestamp: transactionStartTime } = spanToJSON(span); performanceEntries.slice(_performanceCursor).forEach(entry => { + // Navigations can happen long after page load, after a time origin reset. We use the origin from the entry's + // start for all its timings, so its duration stays correct. + const timeOrigin = msToSec(browserPerformanceTimeOrigin(entry.startTime) as number); const startTime = msToSec(entry.startTime); const duration = msToSec( // Inexplicably, Chrome sometimes emits a negative duration. We need to work around this. diff --git a/packages/browser-utils/src/performance/interactions.ts b/packages/browser-utils/src/performance/interactions.ts index 7a3cc89a981d..8ed72ad9c2d8 100644 --- a/packages/browser-utils/src/performance/interactions.ts +++ b/packages/browser-utils/src/performance/interactions.ts @@ -16,13 +16,13 @@ import { import { UI_ACTION_CLICK, UI_INTERACTION_CLICK } from '@sentry/conventions/op'; import type { Client, IntegrationFn, Span, StartSpanOptions, TransactionSource } from '@sentry/core'; import { - browserPerformanceTimeOrigin, debug, defineIntegration, filterCollectedUrl, getActiveSpan, getRootSpan, hasSpanStreamingEnabled, + performanceTimeToSeconds, spanToJSON, UI_ACTION_CLICK_SPAN_NAME_FALLBACK, UI_INTERACTION_CLICK_SPAN_NAME_FALLBACK, @@ -242,7 +242,10 @@ function trackInteractionsAsSpans(client: Client): void { } for (const entry of entries) { if (entry.name === 'click') { - const startTime = msToSec((browserPerformanceTimeOrigin() as number) + entry.startTime); + const startTime = performanceTimeToSeconds(entry.startTime); + if (!startTime) { + return; + } const duration = msToSec(entry.duration); const selector = htmlTreeAsString(entry.target); diff --git a/packages/browser-utils/src/performance/resourceTiming.ts b/packages/browser-utils/src/performance/resourceTiming.ts index 5a711d307cf3..eef2594833f6 100644 --- a/packages/browser-utils/src/performance/resourceTiming.ts +++ b/packages/browser-utils/src/performance/resourceTiming.ts @@ -2,10 +2,10 @@ import type { SpanAttributes } from '@sentry/core'; import { browserPerformanceTimeOrigin } from '@sentry/core'; import { extractNetworkProtocol, getBrowserPerformanceAPI } from './utils'; -function getAbsoluteTime(time: number | undefined): number | undefined { +function getAbsoluteTime(time: number | undefined, timeOrigin: number): number | undefined { // falsy values should be preserved so that we can later on drop undefined values and // preserve 0 vals for cross-origin resources without proper `Timing-Allow-Origin` header. - return time ? ((browserPerformanceTimeOrigin() || performance.timeOrigin) + time) / 1000 : time; + return time ? (timeOrigin + time) / 1000 : time; } /** @@ -28,31 +28,33 @@ export function resourceTimingToSpanAttributes(resourceTiming: PerformanceResour timingSpanData['network.protocol.name'] = name; } - if (!(browserPerformanceTimeOrigin() || getBrowserPerformanceAPI()?.timeOrigin)) { + // Use the origin from the request start for all timings, so the durations between them stay correct. + const timeOrigin = browserPerformanceTimeOrigin(resourceTiming.startTime) || getBrowserPerformanceAPI()?.timeOrigin; + if (!timeOrigin) { return timingSpanData; } return dropUndefinedKeysFromObject({ ...timingSpanData, - 'http.request.redirect_start': getAbsoluteTime(resourceTiming.redirectStart), - 'http.request.redirect_end': getAbsoluteTime(resourceTiming.redirectEnd), + 'http.request.redirect_start': getAbsoluteTime(resourceTiming.redirectStart, timeOrigin), + 'http.request.redirect_end': getAbsoluteTime(resourceTiming.redirectEnd, timeOrigin), - 'http.request.worker_start': getAbsoluteTime(resourceTiming.workerStart), + 'http.request.worker_start': getAbsoluteTime(resourceTiming.workerStart, timeOrigin), - 'http.request.fetch_start': getAbsoluteTime(resourceTiming.fetchStart), + 'http.request.fetch_start': getAbsoluteTime(resourceTiming.fetchStart, timeOrigin), - 'http.request.domain_lookup_start': getAbsoluteTime(resourceTiming.domainLookupStart), - 'http.request.domain_lookup_end': getAbsoluteTime(resourceTiming.domainLookupEnd), + 'http.request.domain_lookup_start': getAbsoluteTime(resourceTiming.domainLookupStart, timeOrigin), + 'http.request.domain_lookup_end': getAbsoluteTime(resourceTiming.domainLookupEnd, timeOrigin), - 'http.request.connect_start': getAbsoluteTime(resourceTiming.connectStart), - 'http.request.secure_connection_start': getAbsoluteTime(resourceTiming.secureConnectionStart), - 'http.request.connection_end': getAbsoluteTime(resourceTiming.connectEnd), + 'http.request.connect_start': getAbsoluteTime(resourceTiming.connectStart, timeOrigin), + 'http.request.secure_connection_start': getAbsoluteTime(resourceTiming.secureConnectionStart, timeOrigin), + 'http.request.connection_end': getAbsoluteTime(resourceTiming.connectEnd, timeOrigin), - 'http.request.request_start': getAbsoluteTime(resourceTiming.requestStart), + 'http.request.request_start': getAbsoluteTime(resourceTiming.requestStart, timeOrigin), - 'http.request.response_start': getAbsoluteTime(resourceTiming.responseStart), - 'http.request.response_end': getAbsoluteTime(resourceTiming.responseEnd), + 'http.request.response_start': getAbsoluteTime(resourceTiming.responseStart, timeOrigin), + 'http.request.response_end': getAbsoluteTime(resourceTiming.responseEnd, timeOrigin), // For TTFB we actually want the relative time from timeOrigin to responseStart // This way, TTFB always measures the "first page load" experience. diff --git a/packages/browser-utils/src/performance/userTiming.ts b/packages/browser-utils/src/performance/userTiming.ts index 02d6fc25694d..24559ba03c5d 100644 --- a/packages/browser-utils/src/performance/userTiming.ts +++ b/packages/browser-utils/src/performance/userTiming.ts @@ -26,11 +26,9 @@ const _userTimingIntegration = ((options: UserTimingOptions = {}) => { name: INTEGRATION_NAME, setup(client) { const performance = getBrowserPerformanceAPI(); - const timeOrigin = browserPerformanceTimeOrigin(); - if (!performance?.getEntries || !timeOrigin) { + if (!performance?.getEntries || !browserPerformanceTimeOrigin()) { return; } - const timeOriginInSeconds = msToSec(timeOrigin); let performanceCursor = 0; client.on('beforeIdleSpanEnd', idleSpan => { @@ -49,6 +47,8 @@ const _userTimingIntegration = ((options: UserTimingOptions = {}) => { continue; } + // Navigations can happen long after page load, after a time origin reset. + const timeOriginInSeconds = msToSec(browserPerformanceTimeOrigin(entry.startTime) as number); const startTime = msToSec(entry.startTime); const absoluteStartTime = timeOriginInSeconds + startTime; diff --git a/packages/browser-utils/src/web-vitals/spans.ts b/packages/browser-utils/src/web-vitals/spans.ts index 424180427141..90ab1102c318 100644 --- a/packages/browser-utils/src/web-vitals/spans.ts +++ b/packages/browser-utils/src/web-vitals/spans.ts @@ -7,6 +7,7 @@ import { getClient, getRootSpan, hasSpanStreamingEnabled, + performanceTimeToSeconds, SEMANTIC_ATTRIBUTE_EXCLUSIVE_TIME, SEMANTIC_ATTRIBUTE_SENTRY_OP, spanToJSON, @@ -193,10 +194,11 @@ export function _sendLcpSpan( DEBUG_BUILD && debug.log(`Sending LCP span (${lcpValue})`); - const performanceTimeOrigin = browserPerformanceTimeOrigin() || 0; // A soft navigation's LCP is measured from the triggering interaction, not the document time // origin. Starting the span there too keeps it inside the navigation span it is parented to and - // keeps its duration equal to the value it reports. + // keeps its duration equal to the reported value. The span's end uses the same origin, even if + // the time origin was reset in between. + const performanceTimeOrigin = browserPerformanceTimeOrigin(navigationStartTime || 0) || 0; const startTime = msToSec(performanceTimeOrigin + (navigationStartTime || 0)); // Without an entry there is no render time to end at, so the span lasts the value it reports, // like an entry-less INP does. Ending at the time origin instead would invert the span. @@ -297,12 +299,12 @@ export function _sendClsSpan( ): void { DEBUG_BUILD && debug.log(`Sending CLS span (${clsValue})`); - const performanceTimeOrigin = browserPerformanceTimeOrigin(); // A CLS of 0 has no shift to place the span at. It is reported when the navigation it was // measured on is already over - the next soft navigation, or pagehide - so the current time would // land it outside that navigation, on the route that follows it. const offset = entry?.startTime ?? navigationStartTime ?? 0; - const startTime = performanceTimeOrigin ? msToSec(performanceTimeOrigin + offset) : timestampInSeconds(); + // CLS is only reported on pagehide, so we use the time origin from when the layout shift happened. + const startTime = performanceTimeToSeconds(offset) ?? timestampInSeconds(); const firstSourceNode = entry?.sources[0]?.node; const selector = entry ? htmlTreeAsString(firstSourceNode) : undefined; const componentName = firstSourceNode ? getComponentName(firstSourceNode) : null; @@ -409,9 +411,9 @@ export function _sendInpSpan( // A web vital span carries the metric, not a real interaction timing, so an INP without an entry // is still worth reporting. It just has no element or interaction type to describe, and is placed // at the start of the navigation it belongs to rather than at the interaction. - const startTime = msToSec( - (browserPerformanceTimeOrigin() as number) + (entry?.startTime ?? metric?.navigationStartTime ?? 0), - ); + // INP is reported on pagehide, often long after the interaction, so we use the time origin from when the + // interaction happened. + const startTime = performanceTimeToSeconds(entry?.startTime ?? metric?.navigationStartTime ?? 0) as number; const duration = msToSec(inpValue); // An INP without an entry has no interaction type to report. It still has to land inside the // `ui.interaction.*` family, because falling outside it would hide exactly the fast navigations diff --git a/packages/browser-utils/test/performance/addPerformanceEntries.test.ts b/packages/browser-utils/test/performance/addPerformanceEntries.test.ts new file mode 100644 index 000000000000..2c687749cab6 --- /dev/null +++ b/packages/browser-utils/test/performance/addPerformanceEntries.test.ts @@ -0,0 +1,79 @@ +import type { Span } from '@sentry/core'; +import * as SentryCore from '@sentry/core'; +import { getClient, getMainCarrier, SentrySpan, setCurrentClient, spanToJSON } from '@sentry/core'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { addPerformanceEntries } from '../../src/performance/entries'; +import { WINDOW } from '../../src/types'; +import { getDefaultClientOptions, TestClient } from '../utils/TestClient'; + +vi.mock('@sentry/core', async () => { + const actual = await vi.importActual('@sentry/core'); + return { + ...actual, + browserPerformanceTimeOrigin: vi.fn(), + }; +}); + +const pageloadOriginMs = 1_000_000; +const sleepDurationMs = 3_600_000; +// The `performance.now()` time from which the reset time origin applies. +const correctionFromMs = 10_000; + +describe('addPerformanceEntries', () => { + beforeEach(() => { + getMainCarrier().__SENTRY__ = undefined; + const client = new TestClient(getDefaultClientOptions({ tracesSampleRate: 1 })); + setCurrentClient(client); + client.init(); + + vi.mocked(SentryCore.browserPerformanceTimeOrigin).mockImplementation((monotonicTimeInMs = 0) => + monotonicTimeInMs < correctionFromMs ? pageloadOriginMs : pageloadOriginMs + sleepDurationMs, + ); + }); + + afterEach(() => { + vi.restoreAllMocks(); + vi.unstubAllGlobals(); + }); + + it('keeps the resource spans of a navigation that happens after a time origin reset', () => { + const resourceStartTime = 12_000; + vi.stubGlobal('addEventListener', vi.fn()); + vi.stubGlobal('location', { origin: 'https://example.com' }); + vi.spyOn(WINDOW.performance, 'getEntries').mockReturnValue([ + { + entryType: 'resource', + name: 'https://example.com/app.js', + initiatorType: 'script', + startTime: resourceStartTime, + duration: 100, + responseEnd: resourceStartTime + 100, + toJSON: () => ({}), + } as PerformanceResourceTiming, + ]); + + const navigationStartTimestamp = (pageloadOriginMs + sleepDurationMs + resourceStartTime - 50) / 1000; + const span = new SentrySpan({ + op: 'navigation', + name: '/next', + sampled: true, + startTimestamp: navigationStartTimestamp, + }); + + const endedSpans: Span[] = []; + getClient()?.on('spanEnd', endedSpan => void endedSpans.push(endedSpan)); + + addPerformanceEntries(span, { ignoreResourceSpans: [] }); + + expect(endedSpans.map(spanToJSON)).toEqual([ + expect.objectContaining({ + start_timestamp: (pageloadOriginMs + sleepDurationMs + resourceStartTime) / 1000, + end_timestamp: (pageloadOriginMs + sleepDurationMs + resourceStartTime + 100) / 1000, + attributes: expect.objectContaining({ + 'sentry.op': 'resource.script', + 'http.request.response_end': (pageloadOriginMs + sleepDurationMs + resourceStartTime + 100) / 1000, + }), + }), + ]); + }); +}); diff --git a/packages/browser-utils/test/web-vitals/spans.test.ts b/packages/browser-utils/test/web-vitals/spans.test.ts index f9182b52d153..c0f165d618b9 100644 --- a/packages/browser-utils/test/web-vitals/spans.test.ts +++ b/packages/browser-utils/test/web-vitals/spans.test.ts @@ -22,6 +22,7 @@ vi.mock('@sentry/core', async () => { return { ...actual, browserPerformanceTimeOrigin: vi.fn(), + performanceTimeToSeconds: vi.fn(), timestampInSeconds: vi.fn(), getCurrentScope: vi.fn(), getClient: vi.fn(), @@ -475,6 +476,22 @@ describe('_sendLcpSpan', () => { expect(mockSpan.end).toHaveBeenCalledWith(3.25); }); + it('uses the time origin from the start of a soft navigation for LCP', () => { + // The soft navigation happens after a time origin reset. + const sleepDurationMs = 3_600_000; + vi.mocked(SentryCore.browserPerformanceTimeOrigin).mockImplementation((monotonicTimeInMs = 0) => + monotonicTimeInMs < 1500 ? 1000 : 1000 + sleepDurationMs, + ); + const entry = { element: { tagName: 'img' } as Element, startTime: 2250 } as LargestContentfulPaint; + + _sendLcpSpan(250, entry, undefined, 2, 'soft-navigation', 2000); + + expect(SentryCoreBrowser.startInactiveSpan).toHaveBeenCalledWith( + expect.objectContaining({ startTime: (1000 + sleepDurationMs + 2000) / 1000 }), + ); + expect(mockSpan.end).toHaveBeenCalledWith((1000 + sleepDurationMs + 2250) / 1000); + }); + it('drops implausible LCP values', () => { _sendLcpSpan(0, undefined); _sendLcpSpan(MAX_PLAUSIBLE_LCP_DURATION + 1, undefined); @@ -497,6 +514,7 @@ describe('_sendClsSpan', () => { beforeEach(() => { vi.mocked(SentryCore.getCurrentScope).mockReturnValue(mockScope as any); vi.mocked(SentryCore.browserPerformanceTimeOrigin).mockReturnValue(1000); + vi.mocked(SentryCore.performanceTimeToSeconds).mockImplementation(time => (1000 + time) / 1000); vi.mocked(SentryCore.timestampInSeconds).mockReturnValue(1.5); vi.mocked(htmlTreeAsString).mockImplementation((node: any) => `<${node?.tagName || 'div'}>`); vi.mocked(SentryCoreBrowser.startInactiveSpan).mockReturnValue(mockSpan as any); @@ -590,6 +608,7 @@ describe('_sendClsSpan', () => { it('falls back to the current time when there is no performance time origin', () => { vi.mocked(SentryCore.browserPerformanceTimeOrigin).mockReturnValue(undefined); + vi.mocked(SentryCore.performanceTimeToSeconds).mockReturnValue(undefined); _sendClsSpan(0, undefined); @@ -612,6 +631,7 @@ describe('_sendInpSpan', () => { beforeEach(() => { vi.mocked(SentryCore.getCurrentScope).mockReturnValue(mockScope as any); vi.mocked(SentryCore.browserPerformanceTimeOrigin).mockReturnValue(1000); + vi.mocked(SentryCore.performanceTimeToSeconds).mockImplementation(time => (1000 + time) / 1000); vi.mocked(htmlTreeAsString).mockReturnValue('