fix(apm/tracing): update pageload op transaction start timestamps (getsentry#2773)

AbhiPrasad · web-flow · commit 7d7f0db4b93f · 2020-07-24T10:21:54.000-04:00
diff --git 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
@@ -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
@@ -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<string, any>, 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
@@ -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);
+  });
+});
