diff --git a/packages/browser-utils/src/performance/entries.ts b/packages/browser-utils/src/performance/entries.ts index f28e60f1cb3e..fdd80b363abd 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,10 @@ 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); + if (!startTime) { + continue; + } const duration = msToSec(entry.duration); if (parentAttributes[SENTRY_OP] === 'navigation' && parentStartTimestamp && startTime < parentStartTimestamp) { @@ -143,12 +147,11 @@ export function startTrackingLongAnimationFrames(): void { return; } for (const entry of list.getEntries() as PerformanceLongAnimationFrameTiming[]) { - if (!entry.scripts[0]) { + const startTime = performanceTimeToSeconds(entry.startTime); + if (!startTime || !entry.scripts[0]) { continue; } - const startTime = msToSec((browserPerformanceTimeOrigin() as number) + entry.startTime); - const { start_timestamp: parentStartTimestamp, attributes: { [SENTRY_OP]: parentOp }, @@ -209,21 +212,25 @@ interface AddPerformanceEntriesOptions { /** Add performance related spans to a transaction */ export function addPerformanceEntries(span: Span, options: AddPerformanceEntriesOptions): void { const performance = getBrowserPerformanceAPI(); - const origin = browserPerformanceTimeOrigin(); - if (!performance?.getEntries || !origin) { + if (!performance?.getEntries) { // Gatekeeper if performance API not available return; } 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 the time origin was corrected for drift. + // We use the origin from the entry's start for all its timings, so its duration stays correct. + const timeOriginInMs = browserPerformanceTimeOrigin(entry.startTime); + if (!timeOriginInMs) { + return; + } + const timeOrigin = msToSec(timeOriginInMs); 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..a4c7dfb8a653 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) { + continue; + } 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..d997a67dad8f 100644 --- a/packages/browser-utils/src/performance/resourceTiming.ts +++ b/packages/browser-utils/src/performance/resourceTiming.ts @@ -1,12 +1,6 @@ import type { SpanAttributes } from '@sentry/core'; import { browserPerformanceTimeOrigin } from '@sentry/core'; -import { extractNetworkProtocol, getBrowserPerformanceAPI } from './utils'; - -function getAbsoluteTime(time: number | undefined): 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; -} +import { extractNetworkProtocol, msToSec } from './utils'; /** * Converts a PerformanceResourceTiming entry to span data for the resource span. Most importantly, @@ -28,10 +22,17 @@ 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); + if (!timeOrigin) { return timingSpanData; } + const getAbsoluteTime = (time: number | undefined): 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. + time ? msToSec(timeOrigin + time) : time; + return dropUndefinedKeysFromObject({ ...timingSpanData, @@ -58,7 +59,7 @@ export function resourceTimingToSpanAttributes(resourceTiming: PerformanceResour // This way, TTFB always measures the "first page load" experience. // see: https://web.dev/articles/ttfb#measure-resource-requests 'http.request.time_to_first_byte': - resourceTiming.responseStart != null ? resourceTiming.responseStart / 1000 : undefined, + resourceTiming.responseStart != null ? msToSec(resourceTiming.responseStart) : undefined, }); } diff --git a/packages/browser-utils/src/performance/userTiming.ts b/packages/browser-utils/src/performance/userTiming.ts index 02d6fc25694d..933af5035f67 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) { return; } - const timeOriginInSeconds = msToSec(timeOrigin); let performanceCursor = 0; client.on('beforeIdleSpanEnd', idleSpan => { @@ -49,6 +47,11 @@ const _userTimingIntegration = ((options: UserTimingOptions = {}) => { continue; } + const timeOriginInMs = browserPerformanceTimeOrigin(entry.startTime); + if (!timeOriginInMs) { + continue; + } + const timeOriginInSeconds = msToSec(timeOriginInMs); 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..46e76519f502 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,11 +194,13 @@ 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. - const startTime = msToSec(performanceTimeOrigin + (navigationStartTime || 0)); + // keeps its duration equal to the reported value. The span's end uses the same origin, even if + // the time origin was corrected in between. + const navigationStart = navigationStartTime || 0; + const performanceTimeOrigin = browserPerformanceTimeOrigin(navigationStart) || 0; + const startTime = msToSec(performanceTimeOrigin + navigationStart); // 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. const endTime = entry ? msToSec(performanceTimeOrigin + entry.startTime) : startTime + msToSec(lcpValue); @@ -297,12 +300,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 +412,12 @@ 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); + if (!startTime) { + return; + } 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..af0631d5d4a6 --- /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 corrected 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 correction', () => { + 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/performance/resourceTiming.test.ts b/packages/browser-utils/test/performance/resourceTiming.test.ts index c6749c6455aa..5809ff80facc 100644 --- a/packages/browser-utils/test/performance/resourceTiming.test.ts +++ b/packages/browser-utils/test/performance/resourceTiming.test.ts @@ -367,117 +367,6 @@ describe('resourceTimingToSpanAttributes', () => { }); }); - describe('fallback to performance.timeOrigin', () => { - it('uses performance.timeOrigin when browserPerformanceTimeOrigin returns null', () => { - // Mock browserPerformanceTimeOrigin to return null for the main check - browserPerformanceTimeOriginSpy.mockReturnValue(null); - - extractNetworkProtocolSpy.mockReturnValue({ - name: '', - version: 'unknown', - }); - - const mockResourceTiming = createMockResourceTiming({ - nextHopProtocol: '', - redirectStart: 20, - fetchStart: 40, - domainLookupStart: 60, - domainLookupEnd: 80, - connectStart: 100, - secureConnectionStart: 120, - connectEnd: 140, - requestStart: 160, - responseStart: 300, - responseEnd: 400, - }); - - const result = resourceTimingToSpanAttributes(mockResourceTiming); - - // When browserPerformanceTimeOrigin returns null, function returns early with only network protocol attributes - expect(result).toEqual({ - 'network.protocol.version': 'unknown', - 'network.protocol.name': '', - }); - }); - - it('uses performance.timeOrigin fallback in getAbsoluteTime when available', () => { - // Mock browserPerformanceTimeOrigin to return 500000 for the main check - browserPerformanceTimeOriginSpy.mockReturnValue(500000); - - extractNetworkProtocolSpy.mockReturnValue({ - name: '', - version: 'unknown', - }); - - const mockResourceTiming = createMockResourceTiming({ - nextHopProtocol: '', - redirectStart: 20, - redirectEnd: 30, - workerStart: 35, - fetchStart: 40, - domainLookupStart: 60, - domainLookupEnd: 80, - connectStart: 100, - secureConnectionStart: 120, - connectEnd: 140, - requestStart: 160, - responseStart: 300, - responseEnd: 400, - }); - - const result = resourceTimingToSpanAttributes(mockResourceTiming); - - expect(result).toEqual({ - 'network.protocol.version': 'unknown', - 'network.protocol.name': '', - 'http.request.redirect_start': 500.02, // (500000 + 20) / 1000 - 'http.request.redirect_end': 500.03, // (500000 + 30) / 1000 - 'http.request.worker_start': 500.035, // (500000 + 35) / 1000 - 'http.request.fetch_start': 500.04, // (500000 + 40) / 1000 - 'http.request.domain_lookup_start': 500.06, // (500000 + 60) / 1000 - 'http.request.domain_lookup_end': 500.08, // (500000 + 80) / 1000 - 'http.request.connect_start': 500.1, // (500000 + 100) / 1000 - 'http.request.secure_connection_start': 500.12, // (500000 + 120) / 1000 - 'http.request.connection_end': 500.14, // (500000 + 140) / 1000 - 'http.request.request_start': 500.16, // (500000 + 160) / 1000 - 'http.request.response_start': 500.3, // (500000 + 300) / 1000 - 'http.request.response_end': 500.4, // (500000 + 400) / 1000 - 'http.request.time_to_first_byte': 0.3, // 300 / 1000 - }); - }); - - it('handles case when neither browserPerformanceTimeOrigin nor performance.timeOrigin is available', () => { - browserPerformanceTimeOriginSpy.mockReturnValue(null); - - extractNetworkProtocolSpy.mockReturnValue({ - name: '', - version: 'unknown', - }); - - // Mock performance.timeOrigin as undefined - const originalPerformance = global.performance; - global.performance = { - ...originalPerformance, - timeOrigin: undefined, - } as any; - - const mockResourceTiming = createMockResourceTiming({ - nextHopProtocol: '', - }); - - const result = resourceTimingToSpanAttributes(mockResourceTiming); - - // When neither timing source is available, should return network protocol attributes for empty string - expect(result).toEqual({ - 'network.protocol.version': 'unknown', - 'network.protocol.name': '', - }); - - // Restore global performance - global.performance = originalPerformance; - }); - }); - describe('edge cases', () => { it("doesn't include undefined timing values", () => { browserPerformanceTimeOriginSpy.mockReturnValue(1000000); diff --git a/packages/browser-utils/test/web-vitals/spans.test.ts b/packages/browser-utils/test/web-vitals/spans.test.ts index f9182b52d153..ed45ddc55280 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 correction. + 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('