feat[apm]: Use Performance API (#2474)

HazAT · rhcarvalho · web-flow · commit 0bc7a4dd9f69 · 2020-03-09T11:45:47.000+01:00
* feat: Use performance api

* feat: Update ops &amp; descriptions

* feat: Handle navigation changes correctly

* chore: Code comments

* Apply suggestions from code review

Co-Authored-By: Rodolfo Carvalho &lt;rodolfo.carvalho@sentry.io&gt;

* chore: CodeReview

* ref: Check for performance API

Co-authored-by: Rodolfo Carvalho &lt;rodolfo.carvalho@sentry.io&gt;
diff --git 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
 
+- [apm] feat: Make use of the `performance` browser API to provide better instrumentation (#2474)
 - [browser] ref: Move global error handler + unhandled promise rejection to instrument
 
 ## 5.13.2
diff --git a/packages/apm/src/integrations/tracing.ts b/packages/apm/src/integrations/tracing.ts
@@ -132,12 +132,17 @@ export class Tracing implements Integration {
 
   private readonly _emitOptionsWarning: boolean = false;
 
+  private static _performanceCursor: number = 0;
+
   /**
    * Constructor for Tracing
    *
    * @param _options TracingOptions
    */
   public constructor(_options?: Partial<TracingOptions>) {
+    if (global.performance) {
+      global.performance.mark('sentry-tracing-init');
+    }
     const defaults = {
       discardBackgroundSpans: true,
       idleTimeout: 500,
@@ -257,6 +262,7 @@ export class Tracing implements Integration {
             event.timestamp - event.start_timestamp < 0);
 
         if (Tracing.options.maxTransactionDuration !== 0 && event.type === 'transaction' && isOutdatedTransaction) {
+          logger.log('[Tracing] Discarded transaction since it maxed out maxTransactionDuration');
           return null;
         }
       }
@@ -316,6 +322,7 @@ export class Tracing implements Integration {
     );
 
     Tracing._activeTransaction = span;
+    Tracing._addOffsetToSpan(`idleTransactionStarted-${Tracing._currentIndex}`, span as SpanClass);
 
     // We need to do this workaround here and not use configureScope
     // Reason being at the time we start the inital transaction we do not have a client bound on the hub yet
@@ -357,11 +364,168 @@ export class Tracing implements Integration {
     const active = Tracing._activeTransaction as SpanClass;
     if (active) {
       logger.log('[Tracing] finishIdleTransaction', active.transaction);
+      Tracing._addPerformanceEntries(active);
       // true = use timestamp of last span
       active.finish(true);
     }
   }
 
+  /**
+   * This uses `performance.getEntries()` to add additional spans to the active transaction.
+   * Also, we update our timings since we consider the timings in this API to be more correct than our manual
+   * measurements.
+   *
+   * @param transactionSpan The transaction span
+   */
+  private static _addPerformanceEntries(transactionSpan: SpanClass): void {
+    if (!global.performance) {
+      // Gatekeeper if performance API not available
+      return;
+    }
+    logger.log('[Tracing] Adding & adjusting spans using Performance API');
+    let navigationOffset = 0;
+    if (
+      transactionSpan.op === 'navigation' &&
+      transactionSpan.data &&
+      typeof transactionSpan.data.offset === 'number'
+    ) {
+      navigationOffset = transactionSpan.data.offset;
+    }
+    // tslint:disable-next-line: completed-docs
+    function addSpan(span: SpanClass): void {
+      if (transactionSpan.spanRecorder) {
+        transactionSpan.spanRecorder.finishSpan(span);
+      }
+    }
+
+    // tslint:disable-next-line: completed-docs
+    function addPerformanceNavigationTiming(parent: SpanClass, entry: { [key: string]: number }, event: string): void {
+      const span = parent.child({
+        description: event,
+        op: 'browser',
+      });
+      span.startTimestamp = parent.startTimestamp + Tracing._msToSec(entry[`${event}Start`]);
+      span.timestamp = parent.startTimestamp + Tracing._msToSec(entry[`${event}End`]);
+      addSpan(span);
+    }
+
+    // tslint:disable-next-line: completed-docs
+    function addRequest(parent: SpanClass, entry: { [key: string]: number }): void {
+      const request = parent.child({
+        description: 'request',
+        op: 'browser',
+      });
+      request.startTimestamp = parent.startTimestamp + Tracing._msToSec(entry.requestStart);
+      request.timestamp = parent.startTimestamp + Tracing._msToSec(entry.responseEnd);
+      addSpan(request);
+      const response = parent.child({
+        description: 'response',
+        op: 'browser',
+      });
+      response.startTimestamp = parent.startTimestamp + Tracing._msToSec(entry.responseStart);
+      response.timestamp = parent.startTimestamp + Tracing._msToSec(entry.responseEnd);
+      addSpan(response);
+    }
+
+    let entryScriptSrc: string | undefined;
+
+    if (global.document) {
+      // tslint:disable-next-line: prefer-for-of
+      for (let i = 0; i < document.scripts.length; i++) {
+        // We go through all scripts on the page and look for 'data-entry'
+        // We remember the name and measure the time between this script finished loading and
+        // our mark 'sentry-tracing-init'
+        if (document.scripts[i].dataset.entry === 'true') {
+          entryScriptSrc = document.scripts[i].src;
+          break;
+        }
+      }
+    }
+
+    let entryScriptStartEndTime: number | undefined;
+    let tracingInitMarkStartTime: number | undefined;
+
+    // tslint:disable: no-unsafe-any
+    performance
+      .getEntries()
+      .slice(Tracing._performanceCursor)
+      .forEach((entry: any) => {
+        const startTime = Tracing._msToSec(entry.startTime as number);
+        const duration = Tracing._msToSec(entry.duration as number);
+
+        switch (entry.entryType) {
+          case 'navigation':
+            addPerformanceNavigationTiming(transactionSpan, entry, 'unloadEvent');
+            addPerformanceNavigationTiming(transactionSpan, entry, 'domContentLoadedEvent');
+            addPerformanceNavigationTiming(transactionSpan, entry, 'loadEvent');
+            addPerformanceNavigationTiming(transactionSpan, entry, 'connect');
+            addPerformanceNavigationTiming(transactionSpan, entry, 'domainLookup');
+            addRequest(transactionSpan, entry);
+            break;
+          case 'mark':
+          case 'paint':
+          case 'measure':
+            const mark = transactionSpan.child({
+              description: `${entry.entryType} ${entry.name}`,
+              op: 'mark',
+            });
+            mark.startTimestamp = transactionSpan.startTimestamp + startTime - navigationOffset;
+            mark.timestamp = mark.startTimestamp + duration;
+            if (tracingInitMarkStartTime === undefined && entry.name === 'sentry-tracing-init') {
+              tracingInitMarkStartTime = mark.startTimestamp;
+            }
+            addSpan(mark);
+            break;
+          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.finishedSpans.map((finishedSpan: SpanClass) => {
+                  if (finishedSpan.description && finishedSpan.description.indexOf(resourceName) !== -1) {
+                    finishedSpan.startTimestamp = transactionSpan.startTimestamp + startTime - navigationOffset;
+                    finishedSpan.timestamp = finishedSpan.startTimestamp + duration;
+                  }
+                });
+              }
+            } else {
+              const resource = transactionSpan.child({
+                description: `${entry.initiatorType} ${resourceName}`,
+                op: `resource`,
+              });
+              resource.startTimestamp = transactionSpan.startTimestamp + startTime - navigationOffset;
+              resource.timestamp = resource.startTimestamp + duration;
+              // We remember the entry script end time to calculate the difference to the first init mark
+              if (entryScriptStartEndTime === undefined && (entryScriptSrc || '').includes(resourceName)) {
+                entryScriptStartEndTime = resource.timestamp;
+              }
+              addSpan(resource);
+            }
+            break;
+          default:
+          // Ignore other entry types.
+        }
+      });
+
+    if (entryScriptStartEndTime !== undefined && tracingInitMarkStartTime !== undefined) {
+      const evaluation = transactionSpan.child({
+        description: 'evaluation',
+        op: `script`,
+      });
+      evaluation.startTimestamp = entryScriptStartEndTime;
+      evaluation.timestamp = tracingInitMarkStartTime;
+      addSpan(evaluation);
+    }
+
+    logger.log('[Tracing] Clearing most performance marks');
+    performance.clearMarks();
+    performance.clearMeasures();
+    performance.clearResourceTimings();
+    Tracing._performanceCursor = Math.max(performance.getEntries().length - 1, 0);
+
+    // tslint:enable: no-unsafe-any
+  }
+
   /**
    * Sets the status of the current active transaction (if there is one)
    */
@@ -373,6 +537,32 @@ export class Tracing implements Integration {
     }
   }
 
+  /**
+   * Adds offset to the span
+   *
+   * @param measureName name of the performance measure
+   * @param span Span to add data.offset to
+   */
+  private static _addOffsetToSpan(measureName: string, span: SpanClass): void {
+    if (global.performance) {
+      const name = `#sentry-${measureName}`;
+      performance.measure(name);
+      const measure = performance.getEntriesByName(name).pop();
+      if (measure) {
+        span.setData('offset', Tracing._msToSec(measure.duration));
+      }
+      performance.clearMeasures(name);
+    }
+  }
+
+  /**
+   * Converts from milliseconds to seconds
+   * @param time time in ms
+   */
+  private static _msToSec(time: number): number {
+    return time / 1000;
+  }
+
   /**
    * Starts tracking for a specifc activity
    *
@@ -403,9 +593,11 @@ export class Tracing implements Integration {
     if (spanContext && _getCurrentHub) {
       const hub = _getCurrentHub();
       if (hub) {
+        const span = hub.startSpan(spanContext);
+        Tracing._addOffsetToSpan(`${name}${Tracing._currentIndex}`, span as SpanClass);
         Tracing._activities[Tracing._currentIndex] = {
           name,
-          span: hub.startSpan(spanContext),
+          span,
         };
       }
     } else {
@@ -445,7 +637,7 @@ export class Tracing implements Integration {
 
     if (activity) {
       logger.log(`[Tracing] popActivity ${activity.name}#${id}`);
-      const span = activity.span;
+      const span = activity.span as SpanClass;
       if (span) {
         if (spanData) {
           Object.keys(spanData).forEach((key: string) => {
@@ -459,6 +651,11 @@ export class Tracing implements Integration {
           });
         }
         span.finish();
+        // If there is an offset in data, we need to shift timestamps towards it
+        if (span.data && typeof span.data.offset === 'number' && typeof span.timestamp === 'number') {
+          span.startTimestamp += span.data.offset;
+          span.timestamp += span.data.offset;
+        }
       }
       // tslint:disable-next-line: no-dynamic-delete
       delete Tracing._activities[id];
diff --git a/packages/apm/src/span.ts b/packages/apm/src/span.ts
@@ -108,7 +108,7 @@ export class Span implements SpanInterface, SpanContext {
   /**
    * Timestamp when the span was created.
    */
-  public readonly startTimestamp: number = timestampWithMs();
+  public startTimestamp: number = timestampWithMs();
 
   /**
    * Internal start time tracked with a monotonic clock.
