From 7d7f0db4b93fc81295323ad1ec05e12df61196d0 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Fri, 24 Jul 2020 10:21:54 -0400 Subject: [PATCH] fix(apm/tracing): update pageload op transaction start timestamps (#2773) --- CHANGELOG.md | 1 + packages/apm/src/integrations/tracing.ts | 36 ++++++++++++----- packages/tracing/src/browser/metrics.ts | 30 +++++++++++--- packages/tracing/test/browser/metrics.test.ts | 40 +++++++++++++++++++ 4 files changed, 91 insertions(+), 16 deletions(-) create mode 100644 packages/tracing/test/browser/metrics.test.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index 5f0e6d729c1e..89c2f94770bf 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,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) +- [apm/tracing] fix: Make sure pageload transactions start timestamps are correctly generated (#2773) ## 5.20.0 diff --git a/packages/apm/src/integrations/tracing.ts b/packages/apm/src/integrations/tracing.ts index d5a7849d4f1a..da478728ded0 100644 --- a/packages/apm/src/integrations/tracing.ts +++ b/packages/apm/src/integrations/tracing.ts @@ -581,7 +581,7 @@ export class Tracing implements Integration { // tslint:disable-next-line: completed-docs function addPerformanceNavigationTiming(parent: Span, entry: { [key: string]: number }, event: string): void { - parent.startChild({ + _startChild(parent, { description: event, endTimestamp: timeOrigin + Tracing._msToSec(entry[`${event}End`]), op: 'browser', @@ -591,14 +591,14 @@ export class Tracing implements Integration { // tslint:disable-next-line: completed-docs function addRequest(parent: Span, entry: { [key: string]: number }): void { - parent.startChild({ + _startChild(parent, { description: 'request', endTimestamp: timeOrigin + Tracing._msToSec(entry.responseEnd), op: 'browser', startTimestamp: timeOrigin + Tracing._msToSec(entry.requestStart), }); - parent.startChild({ + _startChild(parent, { description: 'response', endTimestamp: timeOrigin + Tracing._msToSec(entry.responseEnd), op: 'browser', @@ -648,12 +648,12 @@ export class Tracing implements Integration { case 'mark': case 'paint': case 'measure': - const mark = transactionSpan.startChild({ + const mark = _startChild(transactionSpan, { description: entry.name, + endTimestamp: timeOrigin + startTime + duration, op: entry.entryType, + startTimestamp: timeOrigin + startTime, }); - mark.startTimestamp = timeOrigin + startTime; - mark.endTimestamp = mark.startTimestamp + duration; if (tracingInitMarkStartTime === undefined && entry.name === 'sentry-tracing-init') { tracingInitMarkStartTime = mark.startTimestamp; } @@ -663,12 +663,12 @@ export class Tracing implements Integration { // 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({ + const resource = _startChild(transactionSpan, { description: `${entry.initiatorType} ${resourceName}`, + endTimestamp: timeOrigin + startTime + duration, op: `resource`, + startTimestamp: timeOrigin + startTime, }); - resource.startTimestamp = timeOrigin + startTime; - resource.endTimestamp = resource.startTimestamp + duration; // We remember the entry script end time to calculate the difference to the first init mark if (entryScriptStartEndTime === undefined && (entryScriptSrc || '').indexOf(resourceName) > -1) { entryScriptStartEndTime = resource.endTimestamp; @@ -681,7 +681,7 @@ export class Tracing implements Integration { }); if (entryScriptStartEndTime !== undefined && tracingInitMarkStartTime !== undefined) { - transactionSpan.startChild({ + _startChild(transactionSpan, { description: 'evaluation', endTimestamp: tracingInitMarkStartTime, op: `script`, @@ -1046,3 +1046,19 @@ function historyCallback(_: { [key: string]: any }): void { }); } } + +/** + * Helper function to start child on transactions. This function will make sure that the transaction will + * use the start timestamp of the created child span if it is earlier than the transactions actual + * start timestamp. + */ +export function _startChild(parent: Span, { startTimestamp, ...ctx }: SpanContext): Span { + if (startTimestamp && parent.startTimestamp > startTimestamp) { + parent.startTimestamp = startTimestamp; + } + + return parent.startChild({ + startTimestamp, + ...ctx, + }); +} diff --git a/packages/tracing/src/browser/metrics.ts b/packages/tracing/src/browser/metrics.ts index b8e126323f8d..3083327f22f2 100644 --- a/packages/tracing/src/browser/metrics.ts +++ b/packages/tracing/src/browser/metrics.ts @@ -1,5 +1,7 @@ +import { SpanContext } from '@sentry/types'; import { getGlobalObject, logger } from '@sentry/utils'; +import { Span } from '../span'; import { Transaction } from '../transaction'; import { msToSec } from './utils'; @@ -162,7 +164,7 @@ export class MetricsInstrumentation { }); if (entryScriptStartTimestamp !== undefined && tracingInitMarkStartTime !== undefined) { - transaction.startChild({ + _startChild(transaction, { description: 'evaluation', endTimestamp: tracingInitMarkStartTime, op: 'script', @@ -195,7 +197,7 @@ function addMeasureSpans( const measureStartTimestamp = timeOrigin + startTime; const measureEndTimestamp = measureStartTimestamp + duration; - transaction.startChild({ + _startChild(transaction, { description: entry.name as string, endTimestamp: measureEndTimestamp, op: entry.entryType as string, @@ -223,7 +225,7 @@ function addResourceSpans( const startTimestamp = timeOrigin + startTime; const endTimestamp = startTimestamp + duration; - transaction.startChild({ + _startChild(transaction, { description: `${entry.initiatorType} ${resourceName}`, endTimestamp, op: 'resource', @@ -245,7 +247,7 @@ function addPerformanceNavigationTiming( if (!start || !end) { return; } - transaction.startChild({ + _startChild(transaction, { description: event, endTimestamp: timeOrigin + msToSec(end), op: 'browser', @@ -255,17 +257,33 @@ function addPerformanceNavigationTiming( /** Create request and response related spans */ function addRequest(transaction: Transaction, entry: Record, timeOrigin: number): void { - transaction.startChild({ + _startChild(transaction, { description: 'request', endTimestamp: timeOrigin + msToSec(entry.responseEnd as number), op: 'browser', startTimestamp: timeOrigin + msToSec(entry.requestStart as number), }); - transaction.startChild({ + _startChild(transaction, { description: 'response', endTimestamp: timeOrigin + msToSec(entry.responseEnd as number), op: 'browser', startTimestamp: timeOrigin + msToSec(entry.responseStart as number), }); } + +/** + * Helper function to start child on transactions. This function will make sure that the transaction will + * use the start timestamp of the created child span if it is earlier than the transactions actual + * start timestamp. + */ +export function _startChild(transaction: Transaction, { startTimestamp, ...ctx }: SpanContext): Span { + if (startTimestamp && transaction.startTimestamp > startTimestamp) { + transaction.startTimestamp = startTimestamp; + } + + return transaction.startChild({ + startTimestamp, + ...ctx, + }); +} diff --git a/packages/tracing/test/browser/metrics.test.ts b/packages/tracing/test/browser/metrics.test.ts new file mode 100644 index 000000000000..bc4d3f6ee06d --- /dev/null +++ b/packages/tracing/test/browser/metrics.test.ts @@ -0,0 +1,40 @@ +import { Span, Transaction } from '../../src'; +import { _startChild } from '../../src/browser/metrics'; + +describe('_startChild()', () => { + it('creates a span with given properties', () => { + const transaction = new Transaction({ name: 'test' }); + const span = _startChild(transaction, { + description: 'evaluation', + op: 'script', + }); + + expect(span).toBeInstanceOf(Span); + expect(span.description).toBe('evaluation'); + expect(span.op).toBe('script'); + }); + + it('adjusts the start timestamp if child span starts before transaction', () => { + const transaction = new Transaction({ name: 'test', startTimestamp: 123 }); + const span = _startChild(transaction, { + description: 'script.js', + op: 'resource', + startTimestamp: 100, + }); + + expect(transaction.startTimestamp).toEqual(span.startTimestamp); + expect(transaction.startTimestamp).toEqual(100); + }); + + it('does not adjust start timestamp if child span starts after transaction', () => { + const transaction = new Transaction({ name: 'test', startTimestamp: 123 }); + const span = _startChild(transaction, { + description: 'script.js', + op: 'resource', + startTimestamp: 150, + }); + + expect(transaction.startTimestamp).not.toEqual(span.startTimestamp); + expect(transaction.startTimestamp).toEqual(123); + }); +});