Skip to content

Commit

Permalink
fix(browser): correct timestamp on pageload profiles (#9350)
Browse files Browse the repository at this point in the history
Since there is an unknown elapsed time between document response and
profile start, setting profile timestamp = transaction start timestamp
can significantly skew our profile and cause alignment issue in the
product. This updates the pageload profiles to create independent
timestamps.
  • Loading branch information
JonasBa committed Oct 24, 2023
1 parent f6d66b5 commit c7b8c02
Show file tree
Hide file tree
Showing 4 changed files with 39 additions and 17 deletions.
10 changes: 8 additions & 2 deletions packages/browser/src/profiling/hubextensions.ts
Original file line number Diff line number Diff line change
@@ -1,11 +1,12 @@
/* eslint-disable complexity */
import type { Transaction } from '@sentry/types';
import { logger, uuid4 } from '@sentry/utils';
import { logger, timestampInSeconds, uuid4 } from '@sentry/utils';

import { WINDOW } from '../helpers';
import type { JSSelfProfile } from './jsSelfProfiling';
import {
addProfileToGlobalCache,
isAutomatedPageLoadTransaction,
MAX_PROFILE_DURATION_MS,
shouldProfileTransaction,
startJSSelfProfile,
Expand Down Expand Up @@ -40,6 +41,11 @@ export function onProfilingStartRouteTransaction(transaction: Transaction | unde
*/
export function startProfileForTransaction(transaction: Transaction): Transaction {
// Start the profiler and get the profiler instance.
let startTimestamp: number | undefined;
if (isAutomatedPageLoadTransaction(transaction)) {
startTimestamp = timestampInSeconds() * 1000;
}

const profiler = startJSSelfProfile();

// We failed to construct the profiler, fallback to original transaction.
Expand Down Expand Up @@ -151,7 +157,7 @@ export function startProfileForTransaction(transaction: Transaction): Transactio
// Always call onProfileHandler to ensure stopProfiling is called and the timeout is cleared.
void onProfileHandler().then(
() => {
transaction.setContext('profile', { profile_id: profileId });
transaction.setContext('profile', { profile_id: profileId, start_timestamp: startTimestamp });
originalFinish();
},
() => {
Expand Down
8 changes: 7 additions & 1 deletion packages/browser/src/profiling/integration.ts
Original file line number Diff line number Diff line change
Expand Up @@ -75,6 +75,7 @@ export class BrowserProfilingIntegration implements Integration {
for (const profiledTransaction of profiledTransactionEvents) {
const context = profiledTransaction && profiledTransaction.contexts;
const profile_id = context && context['profile'] && context['profile']['profile_id'];
const start_timestamp = context && context['profile'] && context['profile']['start_timestamp'];

if (typeof profile_id !== 'string') {
__DEBUG_BUILD__ &&
Expand All @@ -99,7 +100,12 @@ export class BrowserProfilingIntegration implements Integration {
continue;
}

const profileEvent = createProfilingEvent(profile_id, profile, profiledTransaction as ProfiledEvent);
const profileEvent = createProfilingEvent(
profile_id,
start_timestamp as number | undefined,
profile,
profiledTransaction as ProfiledEvent,
);
if (profileEvent) {
profilesToAddToEnvelope.push(profileEvent);
}
Expand Down
28 changes: 19 additions & 9 deletions packages/browser/src/profiling/utils.ts
Original file line number Diff line number Diff line change
Expand Up @@ -119,25 +119,30 @@ function getTraceId(event: Event): string {
* Creates a profiling event envelope from a Sentry event.
*/
export function createProfilePayload(
event: ProfiledEvent,
processedProfile: JSSelfProfile,
profile_id: string,
start_timestamp: number | undefined,
processed_profile: JSSelfProfile,
event: ProfiledEvent,
): Profile {
if (event.type !== 'transaction') {
// createProfilingEventEnvelope should only be called for transactions,
// we type guard this behavior with isProfiledTransactionEvent.
throw new TypeError('Profiling events may only be attached to transactions, this should never occur.');
}

if (processedProfile === undefined || processedProfile === null) {
if (processed_profile === undefined || processed_profile === null) {
throw new TypeError(
`Cannot construct profiling event envelope without a valid profile. Got ${processedProfile} instead.`,
`Cannot construct profiling event envelope without a valid profile. Got ${processed_profile} instead.`,
);
}

const traceId = getTraceId(event);
const enrichedThreadProfile = enrichWithThreadInformation(processedProfile);
const transactionStartMs = typeof event.start_timestamp === 'number' ? event.start_timestamp * 1000 : Date.now();
const enrichedThreadProfile = enrichWithThreadInformation(processed_profile);
const transactionStartMs = start_timestamp
? start_timestamp
: typeof event.start_timestamp === 'number'
? event.start_timestamp * 1000
: Date.now();
const transactionEndMs = typeof event.timestamp === 'number' ? event.timestamp * 1000 : Date.now();

const profile: Profile = {
Expand All @@ -164,7 +169,7 @@ export function createProfilePayload(
is_emulator: false,
},
debug_meta: {
images: applyDebugMetadata(processedProfile.resources),
images: applyDebugMetadata(processed_profile.resources),
},
profile: enrichedThreadProfile,
transactions: [
Expand Down Expand Up @@ -575,12 +580,17 @@ export function shouldProfileTransaction(transaction: Transaction): boolean {
* @param event
* @returns {Profile | null}
*/
export function createProfilingEvent(profile_id: string, profile: JSSelfProfile, event: ProfiledEvent): Profile | null {
export function createProfilingEvent(
profile_id: string,
start_timestamp: number | undefined,
profile: JSSelfProfile,
event: ProfiledEvent,
): Profile | null {
if (!isValidProfile(profile)) {
return null;
}

return createProfilePayload(event, profile, profile_id);
return createProfilePayload(profile_id, start_timestamp, profile, event);
}

const PROFILE_MAP: Map<string, JSSelfProfile> = new Map();
Expand Down
10 changes: 5 additions & 5 deletions packages/browser/test/unit/profiling/integration.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -5,11 +5,6 @@ import { BrowserProfilingIntegration } from '../../../src/profiling/integration'
import type { JSSelfProfile } from '../../../src/profiling/jsSelfProfiling';

describe('BrowserProfilingIntegration', () => {
beforeEach(() => {
jest.clearAllMocks();
jest.useRealTimers();
// We will mock the carrier as if it has been initialized by the SDK, else everything is short circuited
});
it('pageload profiles follow regular transaction code path', async () => {
const stopProfile = jest.fn().mockImplementation((): Promise<JSSelfProfile> => {
return Promise.resolve({
Expand Down Expand Up @@ -63,6 +58,11 @@ describe('BrowserProfilingIntegration', () => {
expect(send).toHaveBeenCalledTimes(1);

const profile = send.mock.calls?.[0]?.[0]?.[1]?.[1]?.[1];
const transaction = send.mock.calls?.[0]?.[0]?.[1]?.[0]?.[1];
const profile_timestamp_ms = new Date(profile.timestamp).getTime();
const transaction_timestamp_ms = new Date(transaction.start_timestamp * 1e3).getTime();

expect(profile_timestamp_ms).toBeGreaterThan(transaction_timestamp_ms);
expect(profile.profile.frames[0]).toMatchObject({ function: 'pageload_fn', lineno: 1, colno: 1 });
});
});

0 comments on commit c7b8c02

Please sign in to comment.