From 26efb551ae4a2853f2f518a122efbe773c51d0f1 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Thu, 23 Jul 2020 11:17:02 -0400 Subject: [PATCH 1/3] fix: Make sure fetch requests are being timed correctly --- packages/apm/src/integrations/tracing.ts | 10 +- packages/tracing/src/browser/backgroundtab.ts | 6 +- packages/tracing/src/browser/metrics.ts | 35 ++---- packages/tracing/src/browser/request.ts | 9 +- packages/tracing/src/idletransaction.ts | 4 +- packages/tracing/test/browser/request.test.ts | 115 +++++++++++++++++- 6 files changed, 139 insertions(+), 40 deletions(-) diff --git a/packages/apm/src/integrations/tracing.ts b/packages/apm/src/integrations/tracing.ts index d7cbd77ab4a8..09927f2eae9c 100644 --- a/packages/apm/src/integrations/tracing.ts +++ b/packages/apm/src/integrations/tracing.ts @@ -661,15 +661,7 @@ export class Tracing implements Integration { case 'resource': const resourceName = entry.name.replace(window.location.origin, ''); if (entry.initiatorType === 'xmlhttprequest' || entry.initiatorType === 'fetch') { - // We need to update existing spans with new timing info - if (transactionSpan.spanRecorder) { - transactionSpan.spanRecorder.spans.map((finishedSpan: Span) => { - if (finishedSpan.description && finishedSpan.description.indexOf(resourceName) !== -1) { - finishedSpan.startTimestamp = timeOrigin + startTime; - finishedSpan.endTimestamp = finishedSpan.startTimestamp + duration; - } - }); - } + // do nothing, we can't adjust timings just based on urls } else { const resource = transactionSpan.startChild({ description: `${entry.initiatorType} ${resourceName}`, diff --git a/packages/tracing/src/browser/backgroundtab.ts b/packages/tracing/src/browser/backgroundtab.ts index b0065662d5e4..71d16c4f3ebd 100644 --- a/packages/tracing/src/browser/backgroundtab.ts +++ b/packages/tracing/src/browser/backgroundtab.ts @@ -19,7 +19,11 @@ export function registerBackgroundTabDetection(): void { logger.log( `[Tracing] Transaction: ${SpanStatus.Cancelled} -> since tab moved to the background, op: ${activeTransaction.op}`, ); - activeTransaction.setStatus(SpanStatus.Cancelled); + // We should not set status if it is already set, this prevent important statuses like + // error or data loss from being overwritten on transaction. + if (!activeTransaction.status) { + activeTransaction.setStatus(SpanStatus.Cancelled); + } activeTransaction.setTag('visibilitychange', 'document.hidden'); activeTransaction.finish(); } diff --git a/packages/tracing/src/browser/metrics.ts b/packages/tracing/src/browser/metrics.ts index 606e703bfacb..8d7ed621b449 100644 --- a/packages/tracing/src/browser/metrics.ts +++ b/packages/tracing/src/browser/metrics.ts @@ -1,6 +1,5 @@ import { getGlobalObject, logger } from '@sentry/utils'; -import { Span } from '../span'; import { Transaction } from '../transaction'; import { msToSec } from './utils'; @@ -216,30 +215,20 @@ function addResourceSpans( timeOrigin: number, ): number | undefined { if (entry.initiatorType === 'xmlhttprequest' || entry.initiatorType === 'fetch') { - // We need to update existing spans with new timing info - if (transaction.spanRecorder) { - transaction.spanRecorder.spans.map((finishedSpan: Span) => { - if (finishedSpan.description && finishedSpan.description.indexOf(resourceName) !== -1) { - finishedSpan.startTimestamp = timeOrigin + startTime; - finishedSpan.endTimestamp = finishedSpan.startTimestamp + duration; - } - }); - } - } else { - const startTimestamp = timeOrigin + startTime; - const endTimestamp = startTimestamp + duration; - - transaction.startChild({ - description: `${entry.initiatorType} ${resourceName}`, - endTimestamp, - op: 'resource', - startTimestamp, - }); - - return endTimestamp; + return undefined; } - return undefined; + const startTimestamp = timeOrigin + startTime; + const endTimestamp = startTimestamp + duration; + + transaction.startChild({ + description: `${entry.initiatorType} ${resourceName}`, + endTimestamp, + op: 'resource', + startTimestamp, + }); + + return endTimestamp; } /** Create performance navigation related spans */ diff --git a/packages/tracing/src/browser/request.ts b/packages/tracing/src/browser/request.ts index e66dc97606d2..9b29e65259c3 100644 --- a/packages/tracing/src/browser/request.ts +++ b/packages/tracing/src/browser/request.ts @@ -40,9 +40,9 @@ export interface RequestInstrumentationOptions { } /** Data returned from fetch callback */ -interface FetchData { +export interface FetchData { args: any[]; - fetchData: { + fetchData?: { method: string; url: string; // span_id @@ -123,12 +123,12 @@ export function registerRequestInstrumentation(_options?: Partial boolean, spans: Record, ): void { - if (!shouldCreateSpan(handlerData.fetchData.url) || !handlerData.fetchData) { + if (!handlerData.fetchData || !shouldCreateSpan(handlerData.fetchData.url)) { return; } @@ -154,6 +154,7 @@ function fetchCallback( op: 'http', }); + handlerData.fetchData.__span = span.spanId; spans[span.spanId] = span; const request = (handlerData.args[0] = handlerData.args[0] as string | Request); diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index 2e0b6cde45ad..1b4768df8eab 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -63,7 +63,7 @@ export class IdleTransaction extends Transaction { private _prevHeartbeatString: string | undefined; // Amount of times heartbeat has counted. Will cause transaction to finish after 3 beats. - private _heartbeatCounter: number = 1; + private _heartbeatCounter: number = 0; // We should not use heartbeat if we finished a transaction private _finished: boolean = false; @@ -119,7 +119,7 @@ export class IdleTransaction extends Transaction { if (this._heartbeatCounter >= 3) { logger.log( - `[Tracing] Transaction: ${SpanStatus.Cancelled} -> Heartbeat safeguard kicked in since content hasn't changed for 3 beats`, + `[Tracing] Transaction: ${SpanStatus.DeadlineExceeded} -> Heartbeat safeguard kicked in since content hasn't changed for 3 beats`, ); this.setStatus(SpanStatus.DeadlineExceeded); this.setTag('heartbeat', 'failed'); diff --git a/packages/tracing/test/browser/request.test.ts b/packages/tracing/test/browser/request.test.ts index 5e22c6985db7..62aa7855f3cd 100644 --- a/packages/tracing/test/browser/request.test.ts +++ b/packages/tracing/test/browser/request.test.ts @@ -1,4 +1,25 @@ -import { registerRequestInstrumentation } from '../../src/browser/request'; +import { BrowserClient } from '@sentry/browser'; +import { Hub, makeMain } from '@sentry/hub'; + +import { Span, Transaction } from '../../src'; +import { fetchCallback, FetchData, registerRequestInstrumentation } from '../../src/browser/request'; +import { addExtensionMethods } from '../../src/hubextensions'; + +declare global { + namespace NodeJS { + // tslint:disable-next-line: completed-docs + interface Global { + // Have to mock out Request because it is not defined in jest environment + Request: Request; + } + } +} + +beforeAll(() => { + addExtensionMethods(); + // @ts-ignore + global.Request = {}; +}); const mockAddInstrumentationHandler = jest.fn(); let mockFetchCallback = jest.fn(); @@ -47,3 +68,95 @@ describe('registerRequestInstrumentation', () => { expect(mockXHRCallback()).toBe(undefined); }); }); + +describe('fetchCallback', () => { + let hub: Hub; + let transaction: Transaction; + beforeEach(() => { + hub = new Hub(new BrowserClient({ tracesSampleRate: 1 })); + makeMain(hub); + transaction = hub.startTransaction({ name: 'organizations/users/:userid', op: 'pageload' }) as Transaction; + hub.configureScope(scope => scope.setSpan(transaction)); + }); + + afterEach(() => { + if (transaction) { + transaction.finish(); + } + hub.configureScope(scope => scope.setSpan(undefined)); + }); + + it('does not create span if it should not be created', () => { + const shouldCreateSpan = (url: string): boolean => url === '/organizations'; + const data: FetchData = { + args: ['/users'], + fetchData: { + method: 'GET', + url: '/users', + }, + startTimestamp: 1595509730275, + }; + const spans = {}; + + fetchCallback(data, shouldCreateSpan, spans); + expect(spans).toEqual({}); + }); + + it('does not create span if there is no fetch data', () => { + const shouldCreateSpan = (_: string): boolean => true; + const data: FetchData = { + args: [], + startTimestamp: 1595509730275, + }; + const spans = {}; + + fetchCallback(data, shouldCreateSpan, spans); + expect(spans).toEqual({}); + }); + + it('creates and finishes fetch span on active transaction', () => { + const shouldCreateSpan = (_: string): boolean => true; + const data: FetchData = { + args: ['/users'], + fetchData: { + method: 'GET', + url: '/users', + }, + startTimestamp: 1595509730275, + }; + const spans: Record = {}; + + // Start fetch request + fetchCallback(data, shouldCreateSpan, spans); + const spanKey = Object.keys(spans)[0]; + + const fetchSpan = spans[spanKey]; + expect(fetchSpan).toBeInstanceOf(Span); + expect(fetchSpan.data).toEqual({ + method: 'GET', + type: 'fetch', + url: '/users', + }); + expect(fetchSpan.description).toBe('GET /users'); + expect(fetchSpan.op).toBe('http'); + if (data.fetchData) { + expect(data.fetchData.__span).toBeDefined(); + } else { + fail('Fetch data does not exist'); + } + + const newData = { + ...data, + endTimestamp: data.startTimestamp + 12343234, + }; + + // End fetch request + fetchCallback(newData, shouldCreateSpan, spans); + expect(spans).toEqual({}); + if (transaction.spanRecorder) { + expect(transaction.spanRecorder.spans[1].endTimestamp).toBeDefined(); + } else { + fail('Transaction does not have span recorder'); + } + }); +}); From d0a4be8745614b501e3edc5cfafc8329fcf8f321 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Thu, 23 Jul 2020 11:42:19 -0400 Subject: [PATCH 2/3] CHANGELOG --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0b9af336bd93..5f0e6d729c1e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ - "You miss 100 percent of the chances you don't take. — Wayne Gretzky" — Michael Scott - [react] feat: Add instrumentation for React Router v3 (#2759) +- [apm/tracing] fix: Make sure fetch requests are being timed correctly (#2772) ## 5.20.0 From 234a59829e6cbf0fbfc75df29d1220f670f39e25 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Fri, 24 Jul 2020 09:49:56 -0400 Subject: [PATCH 3/3] fix: Address PR review --- packages/apm/src/integrations/tracing.ts | 6 ++--- packages/tracing/src/browser/metrics.ts | 2 ++ packages/tracing/src/browser/request.ts | 4 ++-- packages/tracing/src/idletransaction.ts | 4 +--- packages/tracing/test/browser/request.test.ts | 24 ++++++++----------- 5 files changed, 18 insertions(+), 22 deletions(-) diff --git a/packages/apm/src/integrations/tracing.ts b/packages/apm/src/integrations/tracing.ts index 09927f2eae9c..d5a7849d4f1a 100644 --- a/packages/apm/src/integrations/tracing.ts +++ b/packages/apm/src/integrations/tracing.ts @@ -660,9 +660,9 @@ export class Tracing implements Integration { break; case 'resource': const resourceName = entry.name.replace(window.location.origin, ''); - if (entry.initiatorType === 'xmlhttprequest' || entry.initiatorType === 'fetch') { - // do nothing, we can't adjust timings just based on urls - } else { + // we already instrument based on fetch and xhr, so we don't need to + // duplicate spans here. + if (entry.initiatorType !== 'xmlhttprequest' && entry.initiatorType !== 'fetch') { const resource = transactionSpan.startChild({ description: `${entry.initiatorType} ${resourceName}`, op: `resource`, diff --git a/packages/tracing/src/browser/metrics.ts b/packages/tracing/src/browser/metrics.ts index 8d7ed621b449..b8e126323f8d 100644 --- a/packages/tracing/src/browser/metrics.ts +++ b/packages/tracing/src/browser/metrics.ts @@ -214,6 +214,8 @@ function addResourceSpans( duration: number, timeOrigin: number, ): number | undefined { + // we already instrument based on fetch and xhr, so we don't need to + // duplicate spans here. if (entry.initiatorType === 'xmlhttprequest' || entry.initiatorType === 'fetch') { return undefined; } diff --git a/packages/tracing/src/browser/request.ts b/packages/tracing/src/browser/request.ts index 9b29e65259c3..9bc952d91a86 100644 --- a/packages/tracing/src/browser/request.ts +++ b/packages/tracing/src/browser/request.ts @@ -104,7 +104,7 @@ export function registerRequestInstrumentation(_options?: Partial { - fetchCallback(handlerData, shouldCreateSpan, spans); + _fetchCallback(handlerData, shouldCreateSpan, spans); }, type: 'fetch', }); @@ -123,7 +123,7 @@ export function registerRequestInstrumentation(_options?: Partial boolean, spans: Record, diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index 1b4768df8eab..c63a24881b85 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -118,9 +118,7 @@ export class IdleTransaction extends Transaction { this._prevHeartbeatString = heartbeatString; if (this._heartbeatCounter >= 3) { - logger.log( - `[Tracing] Transaction: ${SpanStatus.DeadlineExceeded} -> Heartbeat safeguard kicked in since content hasn't changed for 3 beats`, - ); + logger.log(`[Tracing] Transaction finished because of no change for 3 heart beats`); this.setStatus(SpanStatus.DeadlineExceeded); this.setTag('heartbeat', 'failed'); this.finish(); diff --git a/packages/tracing/test/browser/request.test.ts b/packages/tracing/test/browser/request.test.ts index 62aa7855f3cd..de6841e83aac 100644 --- a/packages/tracing/test/browser/request.test.ts +++ b/packages/tracing/test/browser/request.test.ts @@ -2,7 +2,7 @@ import { BrowserClient } from '@sentry/browser'; import { Hub, makeMain } from '@sentry/hub'; import { Span, Transaction } from '../../src'; -import { fetchCallback, FetchData, registerRequestInstrumentation } from '../../src/browser/request'; +import { _fetchCallback, FetchData, registerRequestInstrumentation } from '../../src/browser/request'; import { addExtensionMethods } from '../../src/hubextensions'; declare global { @@ -69,21 +69,17 @@ describe('registerRequestInstrumentation', () => { }); }); -describe('fetchCallback', () => { +describe('_fetchCallback()', () => { let hub: Hub; let transaction: Transaction; - beforeEach(() => { + beforeAll(() => { hub = new Hub(new BrowserClient({ tracesSampleRate: 1 })); makeMain(hub); - transaction = hub.startTransaction({ name: 'organizations/users/:userid', op: 'pageload' }) as Transaction; - hub.configureScope(scope => scope.setSpan(transaction)); }); - afterEach(() => { - if (transaction) { - transaction.finish(); - } - hub.configureScope(scope => scope.setSpan(undefined)); + beforeEach(() => { + transaction = hub.startTransaction({ name: 'organizations/users/:userid', op: 'pageload' }) as Transaction; + hub.configureScope(scope => scope.setSpan(transaction)); }); it('does not create span if it should not be created', () => { @@ -98,7 +94,7 @@ describe('fetchCallback', () => { }; const spans = {}; - fetchCallback(data, shouldCreateSpan, spans); + _fetchCallback(data, shouldCreateSpan, spans); expect(spans).toEqual({}); }); @@ -110,7 +106,7 @@ describe('fetchCallback', () => { }; const spans = {}; - fetchCallback(data, shouldCreateSpan, spans); + _fetchCallback(data, shouldCreateSpan, spans); expect(spans).toEqual({}); }); @@ -127,7 +123,7 @@ describe('fetchCallback', () => { const spans: Record = {}; // Start fetch request - fetchCallback(data, shouldCreateSpan, spans); + _fetchCallback(data, shouldCreateSpan, spans); const spanKey = Object.keys(spans)[0]; const fetchSpan = spans[spanKey]; @@ -151,7 +147,7 @@ describe('fetchCallback', () => { }; // End fetch request - fetchCallback(newData, shouldCreateSpan, spans); + _fetchCallback(newData, shouldCreateSpan, spans); expect(spans).toEqual({}); if (transaction.spanRecorder) { expect(transaction.spanRecorder.spans[1].endTimestamp).toBeDefined();