diff --git a/CHANGELOG.md b/CHANGELOG.md index 4b7ff032ef..4c5fbe7508 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,7 @@ - Do not enable NativeFramesTracking when native is not available ([#3705](https://github.com/getsentry/sentry-react-native/pull/3705)) - Do not initialize the SDK during `expo-router` static routes generation ([#3730](https://github.com/getsentry/sentry-react-native/pull/3730)) - Cancel spans in background doesn't crash in environments without AppState ([#3727](https://github.com/getsentry/sentry-react-native/pull/3727)) +- Fix missing Stall measurements when using new `.end()` span API ([#3737](https://github.com/getsentry/sentry-react-native/pull/3737)) ### Dependencies diff --git a/src/js/tracing/addTracingExtensions.ts b/src/js/tracing/addTracingExtensions.ts index b3ce2c527b..265ad98862 100644 --- a/src/js/tracing/addTracingExtensions.ts +++ b/src/js/tracing/addTracingExtensions.ts @@ -72,11 +72,22 @@ const _patchStartTransaction = (originalStartTransaction: StartTransactionFuncti transaction.finish = (endTimestamp: number | undefined) => { if (reactNativeTracing) { - reactNativeTracing.onTransactionFinish(transaction); + reactNativeTracing.onTransactionFinish(transaction, endTimestamp); } return originalFinish.apply(transaction, [endTimestamp]); }; + + // eslint-disable-next-line @typescript-eslint/unbound-method + const originalEnd = transaction.end; + + transaction.end = (endTimestamp: number | undefined) => { + if (reactNativeTracing) { + reactNativeTracing.onTransactionFinish(transaction, endTimestamp); + } + + return originalEnd.apply(transaction, [endTimestamp]); + }; } return transaction; diff --git a/src/js/tracing/stalltracking.ts b/src/js/tracing/stalltracking.ts index 8d2fef31ac..714cc946c9 100644 --- a/src/js/tracing/stalltracking.ts +++ b/src/js/tracing/stalltracking.ts @@ -122,6 +122,19 @@ export class StallTrackingInstrumentation { this._markSpanFinish(transaction, span.endTimestamp); } }; + + // eslint-disable-next-line @typescript-eslint/unbound-method + const originalSpanEnd = span.end; + + span.end = (endTimestamp?: number) => { + // We let the span determine its own end timestamp as well in case anything gets changed upstream + originalSpanEnd.apply(span, [endTimestamp]); + + // The span should set a timestamp, so this would be defined. + if (span.endTimestamp) { + this._markSpanFinish(transaction, span.endTimestamp); + } + }; }; } } diff --git a/test/mocks/client.ts b/test/mocks/client.ts index 0a83cb404d..2008f288af 100644 --- a/test/mocks/client.ts +++ b/test/mocks/client.ts @@ -13,6 +13,8 @@ import { resolvedSyncPromise } from '@sentry/utils'; export function getDefaultTestClientOptions(options: Partial = {}): TestClientOptions { return { + dsn: 'https://1234@some-domain.com/4505526893805568', + enabled: true, integrations: [], sendClientReports: true, transport: () => @@ -39,6 +41,7 @@ export class TestClient extends BaseClient { public static sendEventCalled?: (event: Event) => void; public event?: Event; + public eventQueue: Array = []; public hint?: EventHint; public session?: Session; @@ -74,6 +77,7 @@ export class TestClient extends BaseClient { public sendEvent(event: Event, hint?: EventHint): void { this.event = event; + this.eventQueue.push(event); this.hint = hint; // In real life, this will get deleted as part of envelope creation. diff --git a/test/tracing/reactnavigation.stalltracking.test.ts b/test/tracing/reactnavigation.stalltracking.test.ts new file mode 100644 index 0000000000..b79a9f86b7 --- /dev/null +++ b/test/tracing/reactnavigation.stalltracking.test.ts @@ -0,0 +1,69 @@ +import { + addGlobalEventProcessor, + getCurrentHub, + getCurrentScope, + getGlobalScope, + getIsolationScope, + setCurrentClient, + startSpanManual, +} from '@sentry/core'; + +import { ReactNativeTracing, ReactNavigationInstrumentation } from '../../src/js'; +import { _addTracingExtensions } from '../../src/js/tracing/addTracingExtensions'; +import { RN_GLOBAL_OBJ } from '../../src/js/utils/worldwide'; +import { getDefaultTestClientOptions, TestClient } from '../mocks/client'; +import { createMockNavigationAndAttachTo } from './reactnavigationutils'; +import { expectStallMeasurements } from './stalltrackingutils'; + +jest.useFakeTimers({ advanceTimers: true }); + +describe('StallTracking with ReactNavigation', () => { + let client: TestClient; + let mockNavigation: ReturnType; + + beforeEach(() => { + RN_GLOBAL_OBJ.__sentry_rn_v5_registered = false; + _addTracingExtensions(); + + getCurrentScope().clear(); + getIsolationScope().clear(); + getGlobalScope().clear(); + + const rnavigation = new ReactNavigationInstrumentation(); + mockNavigation = createMockNavigationAndAttachTo(rnavigation); + + const rnTracing = new ReactNativeTracing({ + routingInstrumentation: rnavigation, + enableStallTracking: true, + enableNativeFramesTracking: false, + enableAppStartTracking: false, + }); + + const options = getDefaultTestClientOptions({ + tracesSampleRate: 1.0, + integrations: [rnTracing], + }); + client = new TestClient(options); + setCurrentClient(client); + client.init(); + + // We have to call this manually as setupOnce is executed once per runtime (global var check) + rnTracing.setupOnce(addGlobalEventProcessor, getCurrentHub); + }); + + afterEach(() => { + jest.clearAllMocks(); + }); + + it('Stall tracking supports idleTransaction with unfinished spans', async () => { + jest.runOnlyPendingTimers(); // Flush app start transaction + mockNavigation.navigateToNewScreen(); + startSpanManual({ name: 'This child span will never finish' }, () => {}); + + jest.runOnlyPendingTimers(); // Flush new screen transaction + + await client.flush(); + + expectStallMeasurements(client.event?.measurements); + }); +}); diff --git a/test/tracing/reactnavigation.ttid.test.tsx b/test/tracing/reactnavigation.ttid.test.tsx index 34e0978500..200257957f 100644 --- a/test/tracing/reactnavigation.ttid.test.tsx +++ b/test/tracing/reactnavigation.ttid.test.tsx @@ -14,7 +14,6 @@ import TestRenderer from 'react-test-renderer'; import * as Sentry from '../../src/js'; import { ReactNavigationInstrumentation } from '../../src/js'; import { TimeToFullDisplay, TimeToInitialDisplay } from '../../src/js/tracing'; -import type { NavigationRoute } from '../../src/js/tracing/reactnavigation'; import { isHermesEnabled, notWeb } from '../../src/js/utils/environment'; import { createSentryEventEmitter } from '../../src/js/utils/sentryeventemitter'; import { RN_GLOBAL_OBJ } from '../../src/js/utils/worldwide'; @@ -22,6 +21,7 @@ import { MOCK_DSN } from '../mockDsn'; import { secondInFutureTimestampMs } from '../testutils'; import type { MockedSentryEventEmitter } from '../utils/mockedSentryeventemitter'; import { emitNativeFullDisplayEvent, emitNativeInitialDisplayEvent } from './mockedtimetodisplaynative'; +import { createMockNavigationAndAttachTo } from './reactnavigationutils'; describe('React Navigation - TTID', () => { let mockedEventEmitter: MockedSentryEventEmitter; @@ -514,78 +514,12 @@ describe('React Navigation - TTID', () => { return sut; } - function createMockNavigationAndAttachTo(sut: ReactNavigationInstrumentation) { - const mockedNavigationContained = mockNavigationContainer(); - const mockedNavigation = { - navigateToNewScreen: () => { - mockedNavigationContained.listeners['__unsafe_action__']({ - // this object is not used by the instrumentation - }); - mockedNavigationContained.currentRoute = { - key: 'new_screen', - name: 'New Screen', - }; - mockedNavigationContained.listeners['state']({ - // this object is not used by the instrumentation - }); - }, - navigateToInitialScreen: () => { - mockedNavigationContained.listeners['__unsafe_action__']({ - // this object is not used by the instrumentation - }); - mockedNavigationContained.currentRoute = { - key: 'initial_screen', - name: 'Initial Screen', - }; - mockedNavigationContained.listeners['state']({ - // this object is not used by the instrumentation - }); - }, - finishAppStartNavigation: () => { - mockedNavigationContained.currentRoute = { - key: 'initial_screen', - name: 'Initial Screen', - }; - mockedNavigationContained.listeners['state']({ - // this object is not used by the instrumentation - }); - }, - }; - sut.registerNavigationContainer(mockRef(mockedNavigationContained)); - - return mockedNavigation; - } - - function mockNavigationContainer(): MockNavigationContainer { - return new MockNavigationContainer(); - } - - function mockRef(wat: T): { current: T } { - return { - current: wat, - }; - } - function getLastTransaction(mockedTransportSend: jest.Mock): TransactionEvent { // Until https://github.com/getsentry/sentry-javascript/blob/a7097d9ba2a74b2cb323da0ef22988a383782ffb/packages/types/src/event.ts#L93 return JSON.parse(JSON.stringify(mockedTransportSend.mock.lastCall[0][1][0][1])); } }); -class MockNavigationContainer { - currentRoute: NavigationRoute = { - key: 'initial_screen', - name: 'Initial Screen', - }; - listeners: Record void> = {}; - addListener: any = jest.fn((eventType: string, listener: (e: any) => void): void => { - this.listeners[eventType] = listener; - }); - getCurrentRoute(): NavigationRoute | undefined { - return this.currentRoute; - } -} - function initSentry(sut: ReactNavigationInstrumentation): { transportSendMock: jest.Mock, Parameters>; } { diff --git a/test/tracing/reactnavigationutils.ts b/test/tracing/reactnavigationutils.ts new file mode 100644 index 0000000000..ef278b6c11 --- /dev/null +++ b/test/tracing/reactnavigationutils.ts @@ -0,0 +1,67 @@ +import type { NavigationRoute, ReactNavigationInstrumentation } from '../../src/js/tracing/reactnavigation'; + +export function createMockNavigationAndAttachTo(sut: ReactNavigationInstrumentation) { + const mockedNavigationContained = mockNavigationContainer(); + const mockedNavigation = { + navigateToNewScreen: () => { + mockedNavigationContained.listeners['__unsafe_action__']({ + // this object is not used by the instrumentation + }); + mockedNavigationContained.currentRoute = { + key: 'new_screen', + name: 'New Screen', + }; + mockedNavigationContained.listeners['state']({ + // this object is not used by the instrumentation + }); + }, + navigateToInitialScreen: () => { + mockedNavigationContained.listeners['__unsafe_action__']({ + // this object is not used by the instrumentation + }); + mockedNavigationContained.currentRoute = { + key: 'initial_screen', + name: 'Initial Screen', + }; + mockedNavigationContained.listeners['state']({ + // this object is not used by the instrumentation + }); + }, + finishAppStartNavigation: () => { + mockedNavigationContained.currentRoute = { + key: 'initial_screen', + name: 'Initial Screen', + }; + mockedNavigationContained.listeners['state']({ + // this object is not used by the instrumentation + }); + }, + }; + sut.registerNavigationContainer(mockRef(mockedNavigationContained)); + + return mockedNavigation; +} + +function mockRef(wat: T): { current: T } { + return { + current: wat, + }; +} + +function mockNavigationContainer(): MockNavigationContainer { + return new MockNavigationContainer(); +} + +export class MockNavigationContainer { + currentRoute: NavigationRoute = { + key: 'initial_screen', + name: 'Initial Screen', + }; + listeners: Record void> = {}; + addListener: any = jest.fn((eventType: string, listener: (e: any) => void): void => { + this.listeners[eventType] = listener; + }); + getCurrentRoute(): NavigationRoute | undefined { + return this.currentRoute; + } +} diff --git a/test/tracing/stalltracking.test.ts b/test/tracing/stalltracking.test.ts index 88a70d32d2..093682e1ea 100644 --- a/test/tracing/stalltracking.test.ts +++ b/test/tracing/stalltracking.test.ts @@ -1,17 +1,23 @@ -import type { Hub } from '@sentry/core'; -import { IdleTransaction, Transaction } from '@sentry/core'; -import type { Event } from '@sentry/types'; - -import { StallTrackingInstrumentation } from '../../src/js/tracing/stalltracking'; - -const mockHub = { - captureEvent: jest.fn(), - getClient: jest.fn(), -}; - -const getLastEvent = (): Event => { - return mockHub.captureEvent.mock.calls[mockHub.captureEvent.mock.calls.length - 1][0]; -}; +import { + addGlobalEventProcessor, + getCurrentHub, + getCurrentScope, + getGlobalScope, + getIsolationScope, + setCurrentClient, + startSpan, + startSpanManual, + startTransaction, +} from '@sentry/core'; +import type { Span } from '@sentry/types'; +import { timestampInSeconds } from '@sentry/utils'; + +import { ReactNativeTracing } from '../../src/js'; +import { _addTracingExtensions } from '../../src/js/tracing/addTracingExtensions'; +import { getDefaultTestClientOptions, TestClient } from '../mocks/client'; +import { expectNonZeroStallMeasurements, expectStallMeasurements } from './stalltrackingutils'; + +jest.useFakeTimers({ advanceTimers: true }); const expensiveOperation = () => { const expensiveObject: { value: string[] } = { @@ -25,505 +31,227 @@ const expensiveOperation = () => { }; describe('StallTracking', () => { - const localHub: Hub = mockHub as unknown as Hub; - - it('Stall tracking detects a JS stall', done => { - const stallTracking = new StallTrackingInstrumentation(); + let client: TestClient; - const transaction = new Transaction( - { - name: 'Test Transaction', - sampled: true, - }, - localHub, - ); - transaction.initSpanRecorder(); + beforeEach(() => { + _addTracingExtensions(); - stallTracking.onTransactionStart(transaction); + getCurrentScope().clear(); + getIsolationScope().clear(); + getGlobalScope().clear(); - expensiveOperation(); - - setTimeout(() => { - stallTracking.onTransactionFinish(transaction); - transaction.finish(); - - const measurements = getLastEvent()?.measurements; - - expect(measurements).toBeDefined(); - if (measurements) { - expect(measurements.stall_count.value).toBeGreaterThan(0); - expect(measurements.stall_count.unit).toBe('none'); - - expect(measurements.stall_longest_time.value).toBeGreaterThan(0); - expect(measurements.stall_longest_time.unit).toBe('millisecond'); + const rnTracing = new ReactNativeTracing({ + enableStallTracking: true, + enableNativeFramesTracking: false, + enableAppStartTracking: false, + }); - expect(measurements.stall_total_time.value).toBeGreaterThan(0); - expect(measurements.stall_total_time.unit).toBe('millisecond'); - } + const options = getDefaultTestClientOptions({ + tracesSampleRate: 1.0, + integrations: [rnTracing], + }); + client = new TestClient(options); + setCurrentClient(client); + client.init(); - done(); - }, 500); + // We have to call this manually as setupOnce is executed once per runtime (global var check) + rnTracing.setupOnce(addGlobalEventProcessor, getCurrentHub); }); - it('Stall tracking detects multiple JS stalls', done => { - const stallTracking = new StallTrackingInstrumentation(); - - const transaction = new Transaction( - { - name: 'Test Transaction', - sampled: true, - }, - localHub, - ); - transaction.initSpanRecorder(); + afterEach(() => { + jest.clearAllMocks(); + }); - stallTracking.onTransactionStart(transaction); + it('Stall tracking detects a JS stall', async () => { + startSpan({ name: 'Stall will happen during this span' }, () => { + expensiveOperation(); + // Ensures at least one iteration of the JS loop check + // (executed the last scheduled one which might be also the first scheduled) + jest.runOnlyPendingTimers(); + }); - expensiveOperation(); + await client.flush(); - setTimeout(() => { - expensiveOperation(); - }, 200); - - setTimeout(() => { - stallTracking.onTransactionFinish(transaction); - transaction.finish(); - const measurements = getLastEvent()?.measurements; - - expect(measurements).toBeDefined(); - if (measurements) { - expect(measurements.stall_count.value).toBeGreaterThanOrEqual(2); - expect(measurements.stall_longest_time.value).toBeGreaterThan(0); - expect(measurements.stall_total_time.value).toBeGreaterThan(0); - } - - done(); - }, 500); + expectNonZeroStallMeasurements(client.event?.measurements); }); - it('Stall tracking timeout is stopped after finishing all transactions (single)', () => { - const stallTracking = new StallTrackingInstrumentation(); + it('Stall tracking detects multiple JS stalls', async () => { + startSpan({ name: 'Stall will happen during this span' }, () => { + expensiveOperation(); + // Ensures at least one iteration of the JS loop check + // (executed the last scheduled one which might be also the first scheduled) + jest.runOnlyPendingTimers(); - const transaction = new Transaction( - { - name: 'Test Transaction', - sampled: true, - }, - localHub, - ); + expensiveOperation(); + jest.runOnlyPendingTimers(); + }); - stallTracking.onTransactionStart(transaction); + await client.flush(); - stallTracking.onTransactionFinish(transaction); - transaction.finish(); + const measurements = client.event?.measurements; + expectNonZeroStallMeasurements(measurements); + expect(measurements?.stall_count.value).toBeGreaterThanOrEqual(2); + }); - const measurements = getLastEvent()?.measurements; + it('Stall tracking timeout is stopped after finishing all transactions (single)', async () => { + startSpan({ name: 'Stall will happen during this span' }, () => { + expensiveOperation(); + // Ensures at least one iteration of the JS loop check + // (executed the last scheduled one which might be also the first scheduled) + jest.runOnlyPendingTimers(); + }); - expect(measurements).not.toBe(null); + await client.flush(); - expect(stallTracking.isTracking).toBe(false); - }); + jest.runAllTimers(); // If tracking would be running there would always be a new timer creating infinite loop - it('Stall tracking timeout is stopped after finishing all transactions (multiple)', done => { - const stallTracking = new StallTrackingInstrumentation(); - - const transaction0 = new Transaction( - { - name: 'Test Transaction 0', - sampled: true, - }, - localHub, - ); - const transaction1 = new Transaction( - { - name: 'Test Transaction 1', - sampled: true, - }, - localHub, - ); - const transaction2 = new Transaction( - { - name: 'Test Transaction 2', - sampled: true, - }, - localHub, - ); - - stallTracking.onTransactionStart(transaction0); - stallTracking.onTransactionStart(transaction1); - - stallTracking.onTransactionFinish(transaction0); - transaction0.finish(); - const measurements0 = getLastEvent()?.measurements; - expect(measurements0).toBeDefined(); - - setTimeout(() => { - stallTracking.onTransactionFinish(transaction1); - transaction1.finish(); - const measurements1 = getLastEvent()?.measurements; - expect(measurements1).toBeDefined(); - }, 600); - - setTimeout(() => { - stallTracking.onTransactionStart(transaction2); - - setTimeout(() => { - stallTracking.onTransactionFinish(transaction2); - transaction2.finish(); - const measurements2 = getLastEvent()?.measurements; - expect(measurements2).not.toBe(null); - - expect(stallTracking.isTracking).toBe(false); - - done(); - }, 200); - }, 500); - - // If the stall tracking does not correctly stop, the process will keep running. We detect this by passing --detectOpenHandles to jest. + expectNonZeroStallMeasurements(client.event?.measurements); }); - it('Stall tracking returns measurements format on finish', () => { - const stallTracking = new StallTrackingInstrumentation(); + it('Stall tracking timeout is stopped after finishing all transactions (multiple)', async () => { + // new `startSpan` API doesn't allow creation of multiple transactions + const t0 = startTransaction({ name: 'Test Transaction 0' }); + const t1 = startTransaction({ name: 'Test Transaction 1' }); + const t2 = startTransaction({ name: 'Test Transaction 2' }); - const transaction = new Transaction( - { - name: 'Test Transaction', - sampled: true, - }, - localHub, - ); + t0.end(); + jest.runOnlyPendingTimers(); + t1.end(); + jest.runOnlyPendingTimers(); + t2.end(); + jest.runOnlyPendingTimers(); - stallTracking.onTransactionStart(transaction); + await client.flush(); - stallTracking.onTransactionFinish(transaction); - transaction.finish(); - const measurements = getLastEvent()?.measurements; + jest.runAllTimers(); // If tracking would be running there would always be a new timer creating infinite loop - expect(measurements).toBeDefined(); + const measurements2 = client.eventQueue.pop()?.measurements; + const measurements1 = client.eventQueue.pop()?.measurements; + const measurements0 = client.eventQueue.pop()?.measurements; - if (measurements) { - expect(measurements.stall_count.value).toBe(0); - expect(measurements.stall_longest_time.value).toBe(0); - expect(measurements.stall_total_time.value).toBe(0); - } + expectStallMeasurements(measurements0); + expectStallMeasurements(measurements1); + expectStallMeasurements(measurements2); }); - it("Stall tracking returns null on a custom endTimestamp that is not a span's", () => { - const stallTracking = new StallTrackingInstrumentation(); - - const transaction = new Transaction( - { - name: 'Test Transaction', - sampled: true, - }, - localHub, - ); - - stallTracking.onTransactionStart(transaction); + it('Stall tracking returns measurements format on finish', async () => { + startSpan({ name: 'Stall will happen during this span' }, () => { + // no expensive operation + }); - stallTracking.onTransactionFinish(transaction, Date.now() / 1000); - transaction.finish(); - const measurements = getLastEvent()?.measurements; + await client.flush(); - expect(measurements).toBeUndefined(); + expectStallMeasurements(client.event?.measurements); }); - it('Stall tracking supports endTimestamp that is from the last span (trimEnd case)', done => { - const stallTracking = new StallTrackingInstrumentation(); - - const transaction = new Transaction( - { - name: 'Test Transaction', - trimEnd: true, - sampled: true, - }, - localHub, - ); - transaction.initSpanRecorder(); - - stallTracking.onTransactionStart(transaction); - - const span = transaction.startChild({ - description: 'Test Span', + it("Stall tracking returns null on a custom endTimestamp that is not a span's", async () => { + startSpanManual({ name: 'Stall will happen during this span', trimEnd: false }, (rootSpan: Span | undefined) => { + rootSpan!.end(timestampInSeconds()); }); - let spanFinishTime: number | undefined; - - setTimeout(() => { - spanFinishTime = Date.now() / 1000; - - span.finish(spanFinishTime); - }, 100); - - setTimeout(() => { - expect(spanFinishTime).toEqual(expect.any(Number)); - - stallTracking.onTransactionFinish(transaction); - transaction.finish(); - const measurements = getLastEvent()?.measurements; + await client.flush(); - expect(measurements).toBeDefined(); - - if (measurements) { - expect(measurements.stall_count.value).toEqual(expect.any(Number)); - expect(measurements.stall_longest_time.value).toEqual(expect.any(Number)); - expect(measurements.stall_total_time.value).toEqual(expect.any(Number)); - } - - done(); - }, 400); + expect(client.event?.measurements).toBeUndefined(); }); - it('Stall tracking rejects endTimestamp that is from the last span if trimEnd is false (trimEnd case)', done => { - const stallTracking = new StallTrackingInstrumentation(); - - const transaction = new Transaction( - { - name: 'Test Transaction', - trimEnd: false, - sampled: true, - }, - localHub, - ); - transaction.initSpanRecorder(); - - stallTracking.onTransactionStart(transaction); - - const span = transaction.startChild({ - description: 'Test Span', + it('Stall tracking supports endTimestamp that is from the last span (trimEnd case)', async () => { + startSpanManual({ name: 'Stall will happen during this span', trimEnd: true }, (rootSpan: Span | undefined) => { + let childSpanEnd: number | undefined = undefined; + startSpanManual({ name: 'This is a child of the active span' }, (childSpan: Span | undefined) => { + childSpanEnd = timestampInSeconds(); + childSpan!.end(childSpanEnd); + jest.runOnlyPendingTimers(); + }); + jest.runOnlyPendingTimers(); + rootSpan!.end(childSpanEnd); }); - let spanFinishTime: number | undefined; + await client.flush(); - setTimeout(() => { - spanFinishTime = Date.now() / 1000; - - span.finish(spanFinishTime); - }, 100); - - setTimeout(() => { - expect(spanFinishTime).toEqual(expect.any(Number)); - - stallTracking.onTransactionFinish(transaction, spanFinishTime); - transaction.finish(); - const measurements = getLastEvent()?.measurements; - - expect(measurements).toBeUndefined(); - - done(); - }, 400); + expectStallMeasurements(client.event?.measurements); }); - it('Stall tracking rejects endTimestamp even if it is a span time (custom endTimestamp case)', done => { - const stallTracking = new StallTrackingInstrumentation(); - - const transaction = new Transaction( - { - name: 'Test Transaction', - sampled: true, - }, - localHub, - ); - transaction.initSpanRecorder(); - - stallTracking.onTransactionStart(transaction); - - const span = transaction.startChild({ - description: 'Test Span', + it('Stall tracking rejects endTimestamp that is from the last span if trimEnd is false (trimEnd case)', async () => { + startSpanManual({ name: 'Stall will happen during this span', trimEnd: false }, (rootSpan: Span | undefined) => { + let childSpanEnd: number | undefined = undefined; + startSpanManual({ name: 'This is a child of the active span' }, (childSpan: Span | undefined) => { + childSpanEnd = timestampInSeconds(); + childSpan!.end(childSpanEnd); + jest.runOnlyPendingTimers(); + }); + jest.runOnlyPendingTimers(); + rootSpan!.end(childSpanEnd); }); - let spanFinishTime: number | undefined; - - setTimeout(() => { - spanFinishTime = Date.now() / 1000; - - span.finish(spanFinishTime); - }, 100); - - setTimeout(() => { - expect(spanFinishTime).toEqual(expect.any(Number)); + await client.flush(); - if (typeof spanFinishTime === 'number') { - stallTracking.onTransactionFinish(transaction, spanFinishTime + 0.015); - transaction.finish(); - const evt = getLastEvent(); - const measurements = evt?.measurements; - - expect(measurements).toBeUndefined(); - } - - done(); - }, 400); + expect(client.event?.measurements).toBeUndefined(); }); - it('Stall tracking supports idleTransaction with unfinished spans', async () => { - jest.useFakeTimers(); - const stallTracking = new StallTrackingInstrumentation(); - const idleTransaction = new IdleTransaction( - { - name: 'Test Transaction', - trimEnd: true, - sampled: true, - }, - localHub, - undefined, - undefined, - ); - idleTransaction.initSpanRecorder(); - - stallTracking.onTransactionStart(idleTransaction); - - idleTransaction.registerBeforeFinishCallback((_, endTimestamp) => { - stallTracking.onTransactionFinish(idleTransaction, endTimestamp); + it('Stall tracking rejects endTimestamp even if it is a span time (custom endTimestamp case)', async () => { + startSpanManual({ name: 'Stall will happen during this span', trimEnd: false }, (rootSpan: Span | undefined) => { + let childSpanEnd: number | undefined = undefined; + startSpanManual({ name: 'This is a child of the active span' }, (childSpan: Span | undefined) => { + childSpanEnd = timestampInSeconds(); + childSpan!.end(childSpanEnd); + jest.runOnlyPendingTimers(); + }); + jest.runOnlyPendingTimers(); + rootSpan!.end(childSpanEnd! + 0.1); }); - // Span is never finished. - idleTransaction.startChild({ - description: 'Test Span', - }); - - await Promise.resolve(); - jest.advanceTimersByTime(100); - - stallTracking.onTransactionFinish(idleTransaction, +0.015); - idleTransaction.finish(); + await client.flush(); - const measurements = getLastEvent()?.measurements; - - expect(measurements).toBeDefined(); - - expect(measurements?.stall_count.value).toEqual(expect.any(Number)); - expect(measurements?.stall_longest_time.value).toEqual(expect.any(Number)); - expect(measurements?.stall_total_time.value).toEqual(expect.any(Number)); - - jest.runOnlyPendingTimers(); - jest.useRealTimers(); + expect(client.event?.measurements).toBeUndefined(); }); - it('Stall tracking ignores unfinished spans in normal transactions', done => { - const stallTracking = new StallTrackingInstrumentation(); - - const transaction = new Transaction( - { - name: 'Test Transaction', - trimEnd: true, - sampled: true, - }, - localHub, - ); - transaction.initSpanRecorder(); - - stallTracking.onTransactionStart(transaction); - - // Span is never finished. - transaction.startChild({ - description: 'Test Span', - }); - - // Span will be finished - const span = transaction.startChild({ - description: 'To Finish', + it('Stall tracking ignores unfinished spans in normal transactions', async () => { + startSpan({ name: 'Stall will happen during this span', trimEnd: true }, () => { + startSpan({ name: 'This child span will finish' }, () => { + jest.runOnlyPendingTimers(); + }); + startSpanManual({ name: 'This child span never finishes' }, () => { + jest.runOnlyPendingTimers(); + }); + jest.runOnlyPendingTimers(); }); - setTimeout(() => { - span.finish(); - }, 100); - - setTimeout(() => { - stallTracking.onTransactionFinish(transaction); - transaction.finish(); - const measurements = getLastEvent()?.measurements; - - expect(measurements).toBeDefined(); + await client.flush(); - if (measurements) { - expect(measurements.stall_count.value).toEqual(expect.any(Number)); - expect(measurements.stall_longest_time.value).toEqual(expect.any(Number)); - expect(measurements.stall_total_time.value).toEqual(expect.any(Number)); - } - - done(); - }, 500); + expectStallMeasurements(client.event?.measurements); }); - it('Stall tracking only measures stalls inside the final time when trimEnd is used', done => { - const stallTracking = new StallTrackingInstrumentation(); - - const transaction = new Transaction( - { - name: 'Test Transaction', - trimEnd: true, - sampled: true, - }, - localHub, - ); - transaction.initSpanRecorder(); - - stallTracking.onTransactionStart(transaction); + it('Stall tracking only measures stalls inside the final time when trimEnd is used', async () => { + startSpan({ name: 'Stall will happen during this span', trimEnd: true }, () => { + startSpan({ name: 'This child span contains expensive operation' }, () => { + expensiveOperation(); + jest.runOnlyPendingTimers(); + }); - // Span will be finished - const span = transaction.startChild({ - description: 'To Finish', + expensiveOperation(); // This should not be recorded + jest.runOnlyPendingTimers(); }); - setTimeout(() => { - span.finish(); - }, 200); - - setTimeout(() => { - stallTracking.onTransactionFinish(transaction); - transaction.finish(); - const measurements = getLastEvent()?.measurements; - - expect(measurements).toBeDefined(); + await client.flush(); - if (measurements) { - expect(measurements.stall_count.value).toEqual(1); - expect(measurements.stall_longest_time.value).toEqual(expect.any(Number)); - expect(measurements.stall_total_time.value).toEqual(expect.any(Number)); - } - - done(); - }, 500); - - setTimeout(() => { - // this should be run after the span finishes, and not logged. - expensiveOperation(); - }, 300); - - expensiveOperation(); + const measurements = client.event?.measurements; + expectNonZeroStallMeasurements(measurements); + expect(measurements?.stall_count.value).toEqual(1); }); - it('Stall tracking does not track the first transaction if more than 10 are running', () => { - const stallTracking = new StallTrackingInstrumentation(); - - const transactions = new Array(11).fill(0).map((_, i) => { - const transaction = new Transaction( - { - name: `Test Transaction ${i}`, - sampled: true, - }, - localHub, - ); + it('Stall tracking does not track the first transaction if more than 10 are running', async () => { + // new `startSpan` API doesn't allow creation of multiple transactions + new Array(11) + .fill(undefined) + .map((_, i) => { + return startTransaction({ name: `Test Transaction ${i}` }); + }) + .forEach(t => { + t.end(); + }); - stallTracking.onTransactionStart(transaction); + await client.flush(); - return transaction; - }); - - stallTracking.onTransactionFinish(transactions[0]); - transactions[0].finish(); - const measurements0 = getLastEvent()?.measurements; - expect(measurements0).toBeUndefined(); - - stallTracking.onTransactionFinish(transactions[1]); - transactions[1].finish(); - const measurements1 = getLastEvent()?.measurements; - expect(measurements1).toBeDefined(); - - transactions.slice(2).forEach(transaction => { - stallTracking.onTransactionFinish(transaction); - transaction.finish(); - }); + expect(client.eventQueue[0].measurements).toBeUndefined(); }); }); diff --git a/test/tracing/stalltrackingutils.ts b/test/tracing/stalltrackingutils.ts new file mode 100644 index 0000000000..edcf8956c7 --- /dev/null +++ b/test/tracing/stalltrackingutils.ts @@ -0,0 +1,27 @@ +import type { Measurements } from '@sentry/types'; + +export function expectStallMeasurements(measurements: Measurements | undefined) { + expect(measurements).toBeDefined(); + + expect(measurements?.stall_count.value).toBeGreaterThanOrEqual(0); + expect(measurements?.stall_count.unit).toBe('none'); + + expect(measurements?.stall_longest_time.value).toBeGreaterThanOrEqual(0); + expect(measurements?.stall_longest_time.unit).toBe('millisecond'); + + expect(measurements?.stall_total_time.value).toBeGreaterThanOrEqual(0); + expect(measurements?.stall_total_time.unit).toBe('millisecond'); +} + +export function expectNonZeroStallMeasurements(measurements: Measurements | undefined) { + expect(measurements).toBeDefined(); + + expect(measurements?.stall_count.value).toBeGreaterThan(0); + expect(measurements?.stall_count.unit).toBe('none'); + + expect(measurements?.stall_longest_time.value).toBeGreaterThan(0); + expect(measurements?.stall_longest_time.unit).toBe('millisecond'); + + expect(measurements?.stall_total_time.value).toBeGreaterThan(0); + expect(measurements?.stall_total_time.unit).toBe('millisecond'); +}