fix(content): Fix buggy timing metrics

Because:
- We could see in Sentry that various times provided to metrics endpoint were consistently off.

This Commit:
- Creates an abstraction around the performance API to isolate some of its complexities.
 - Tries to use the performance API where possible.
- Address discrepancies between performance API timestamps and system time.. The assumption that the clock used by Date and the clock used by the performance API  are somehow in sync is likely the reason for the generation of erroneous data.  It is very likely that there is a significant clock skew found between the monotonic clock used by the performance API and current state of the system clock. There appears to be a lot of nuance here, and the exact way this plays out depends on the OS, browser, and browser version, and if the machine has been put into sleep mode. One thing is clear, mixing the performance API timestamps and Date timestamps appears to not work very well.
- Adds support for using L2 timings, and uses these timings when possible.
- Adds a performance fallback class that can fill in for situations where the performance API is missing.
  - Adds some logic around timing values that should be ignored when set to 0.
  - Prefers the performance API's clock when possible, since it’s resilient to skewed metrics due to a computer being put to sleep.
- For browser’s that do not support the performance api, we will not produce timing data.
- For browser’s that do not support the performance api, we will  make a best effort to produce timing data; however, if we detect the machine enters sleep mode during data collection, the data will be deemed unreliable and will not be recorded.

packages/fxa-content-server/app/scripts/lib/metrics.js

@@ -145,7 +145,14 @@ function marshallEmailDomain(email) {
 }
 
 function Metrics(options = {}) {
-  this._speedTrap = new SpeedTrap();
+
+  // Supplying a custom start time is a good way to create invalid metrics. We
+  // are deprecating this option.
+  if (options.startTime !== undefined) {
+    throw new Error('Supplying an external start time is no longer supported!');
+  }
+
+  this._speedTrap = new SpeedTrap(options);
   this._speedTrap.init();
 
   // `timers` and `events` are part of the public API
@@ -184,9 +191,7 @@ function Metrics(options = {}) {
   this._screenWidth = options.screenWidth || NOT_REPORTED_VALUE;
   this._sentryMetrics = options.sentryMetrics;
   this._service = options.service || NOT_REPORTED_VALUE;
-  // if navigationTiming is supported, the baseTime will be from
-  // navigationTiming.navigationStart, otherwise Date.now().
-  this._startTime = options.startTime || this._speedTrap.baseTime;
+  this._startTime = this._speedTrap.baseTime;
   this._syncEngines = options.syncEngines || [];
   this._uid = options.uid || NOT_REPORTED_VALUE;
   this._metricsEnabled = options.metricsEnabled ?? true;
@@ -448,7 +453,7 @@ _.extend(Metrics.prototype, Backbone.Events, {
       experiments: flattenHashIntoArrayOfObjects(this._activeExperiments),
       flowBeginTime: flowData.flowBeginTime,
       flowId: flowData.flowId,
-      flushTime: Date.now(),
+      flushTime: this._speedTrap.now(),
       initialView: this._initialViewName,
       isSampledUser: this._isSampledUser,
       lang: this._lang,
@@ -529,6 +534,17 @@ _.extend(Metrics.prototype, Backbone.Events, {
     if (!this._metricsEnabled) {
       return Promise.resolve(true);
     }
+
+    // This case will only be hit for legacy browsers that
+    // don't support the performance API and went into sleep
+    // state. During metrics collection. In these cases the
+    // metrics generated are not reliable and should not be
+    // reported.
+    if (this._speedTrap.isInSuspectState()) {
+      console.log('suspect state detected!!!')
+      return Promise.resolve()
+    }
+
     const url = `${this._collector}/metrics`;
     const payload = JSON.stringify(data);
 

packages/fxa-content-server/app/tests/spec/lib/metrics.js

@@ -15,6 +15,7 @@ import Notifier from 'lib/channels/notifier';
 import sinon from 'sinon';
 import SubscriptionModel from 'models/subscription';
 import WindowMock from '../../mocks/window';
+import { getFallbackPerformanceApi, getRealPerformanceApi } from 'fxa-shared/speed-trap/performance-factory';
 
 const FLOW_ID =
   '0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef';
@@ -23,13 +24,24 @@ const MARKETING_CAMPAIGN = 'campaign1';
 const MARKETING_CAMPAIGN_URL = 'https://accounts.firefox.com';
 const BAD_METRIC_ERROR_PREFIX = 'Bad metric encountered:';
 
-describe('lib/metrics', () => {
+
+const performanceApis = [
+  { name: 'real - L2', api: getRealPerformanceApi(), useL1Timings: false },
+  { name: 'real - L1', api: getRealPerformanceApi(), useL1Timings: true },
+  { name: 'fallback', api: getFallbackPerformanceApi() }
+]
+
+for (const performanceApi of performanceApis) {
+
+
+describe('lib/metrics/' + performanceApi.name, () => {
   let environment;
   let metrics;
   let notifier;
   let sentryMock;
   let windowMock;
   let xhr;
+  let startTime;
 
   function createMetrics(options = {}) {
     environment = new Environment(windowMock);
@@ -45,6 +57,8 @@ describe('lib/metrics', () => {
 
     metrics = new Metrics(
       _.defaults(options, {
+        performance: performanceApi.api,
+        useL1Timings: performanceApi.useL1Timings,
         brokerType: 'fx-desktop-v3',
         clientHeight: 966,
         clientWidth: 1033,
@@ -62,7 +76,6 @@ describe('lib/metrics', () => {
         screenWidth: 1600,
         sentryMetrics: sentryMock,
         service: 'sync',
-        startTime: 1439233336187,
         uid: '0ae7fe2b244f4a789857dff3ae263927',
         uniqueUserId: '0ae7fe2b-244f-4a78-9857-dff3ae263927',
         utmCampaign: 'utm_campaign',
@@ -74,6 +87,9 @@ describe('lib/metrics', () => {
         xhr,
       })
     );
+
+    // Peak at start time.
+    startTime = metrics._startTime;
     sinon.spy(metrics, '_initializeSubscriptionModel');
   }
 
@@ -330,7 +346,7 @@ describe('lib/metrics', () => {
       assert.equal(filteredData.screen.clientWidth, 1033);
       assert.equal(filteredData.screen.clientHeight, 966);
       assert.equal(filteredData.service, 'sync');
-      assert.equal(filteredData.startTime, 1439233336187);
+      assert.equal(filteredData.startTime, startTime);
       assert.deepEqual(filteredData.syncEngines, []);
 
       assert.equal(filteredData.uid, '0ae7fe2b244f4a789857dff3ae263927');
@@ -1121,3 +1137,5 @@ describe('lib/metrics', () => {
     });
   });
 });
+
+}

packages/fxa-shared/speed-trap/events.js

@@ -5,13 +5,17 @@
 class Events {
   init(options) {
     this.events = [];
-    this.baseTime = options.baseTime;
+
+    if (!options || !options.performance) {
+      throw new Error('options.performance is required!')
+    }
+    this.performance = options.performance;
   }
 
   capture(name) {
     this.events.push({
       type: name,
-      offset: Date.now() - this.baseTime,
+      offset: this.performance.now(),
     });
   }
 

packages/fxa-shared/speed-trap/index.js

@@ -1,2 +1,10 @@
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+// Note, this code was ported back into fxa for ease of maintenance. The source originated
+// from https://www.npmjs.com/package/speed-trap. The actual github repo for this package
+// no longer exists.
+
 import { default as SpeedTrap } from './speed-trap';
 export default SpeedTrap;

packages/fxa-shared/speed-trap/navigation-timing.js

@@ -2,66 +2,108 @@
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
-const NAVIGATION_TIMING_FIELDS = {
-  navigationStart: undefined,
-  unloadEventStart: undefined,
-  unloadEventEnd: undefined,
-  redirectStart: undefined,
-  redirectEnd: undefined,
-  fetchStart: undefined,
-  domainLookupStart: undefined,
-  domainLookupEnd: undefined,
-  connectStart: undefined,
-  connectEnd: undefined,
-  secureConnectionStart: undefined,
-  requestStart: undefined,
-  responseStart: undefined,
-  responseEnd: undefined,
-  domLoading: undefined,
-  domInteractive: undefined,
-  domContentLoadedEventStart: undefined,
-  domContentLoadedEventEnd: undefined,
-  domComplete: undefined,
-  loadEventStart: undefined,
-  loadEventEnd: undefined,
-};
-
-var navigationTiming;
-try {
-  // eslint-disable-next-line no-undef
-  navigationTiming = window.performance.timing;
-} catch (e) {
-  // NOOP
-}
+import {NAVIGATION_TIMING_FIELDS, OPTIONAL_NAVIGATION_TIMING_FIELDS} from './timing-fields';
 
-if (!navigationTiming) {
-  navigationTiming = Object.create(NAVIGATION_TIMING_FIELDS);
+const L2TimingsMap = {
+  'navigationStart': 'startTime',
+  'domLoading': 'domContentLoadedEventStart'
 }
 
-var navigationStart = navigationTiming.navigationStart || Date.now();
+const TimingVersions = {
+  L2: 'L2',
+  L1: 'L1',
+  UNKNOWN: ''
+}
 
 class NavigationTiming {
-  init(options) {
-    options = options || {};
-    this.navigationTiming = options.navigationTiming || navigationTiming;
-    this.baseTime = navigationStart;
+  init(opts) {
+
+    // A performance api must be provided
+    if (!opts || !opts.performance) {
+      throw new Error('opts.performance is required!')
+    }
+    this.performance = opts.performance;
+    this.useL1Timings = opts.useL1Timings;
   }
 
-  get() {
-    return this.navigationTiming;
+  getTimingVersion () {
+    const version = this.getL2Timings() ? TimingVersions.L2 :
+                    this.getL1Timings() ? TimingVersions.L1 :
+                    TimingVersions.UNKNOWN;
+    return version;
+  }
+
+  getL2Timings() {
+    if (
+      !!this.performance &&
+      !!this.performance.getEntriesByType &&
+      !!this.performance.getEntriesByType('navigation'))
+    {
+      return this.performance.getEntriesByType('navigation')[0]
+    }
+  }
+
+  getL1Timings() {
+    return this.performance.timing;
   }
 
   diff() {
-    var diff = {};
-    var baseTime = this.baseTime;
 
-    for (var key in NAVIGATION_TIMING_FIELDS) {
-      var timing = this.navigationTiming[key];
+    // If we are using our fallback performance api (ie window.performance
+    // doesn't  exist), don't return anything.
+    if (this.performance.unreliable === true) {
+      return undefined;
+    }
+
+    const diff = {}
+    const l2Timings = this.getL2Timings();
+    const l1Timings = this.getL1Timings();
+
+    function diffL1() {
+      // Make navigation timings relative to navigation start.
+      for (const key in NAVIGATION_TIMING_FIELDS) {
+        const timing = l1Timings[key];
+
+        if (timing === 0 && OPTIONAL_NAVIGATION_TIMING_FIELDS.indexOf(key) >= 0) {
+          // A time value of 0 for certain fields indicates a non-applicable value. Set to null.
+          diff[key] = null;
+        }
+        else {
+          // Compute the delta relative to navigation start. This removes any
+          // ambiguity around what the 'start' or 'baseTime' time is. Since we
+          // are sure the current set of navigation timings were created using
+          // the same kind of clock, this seems like the safest way to do this.
+          diff[key] = timing - this.performance.timing.navigationStart;
+        }
+      }
+    }
+
+    function diffL2 () {
+      // If we have level 2 timings we can almost return the timings directly. We just have massage
+      // a couple fields to keep it backwards compatible.
+      for (const key in NAVIGATION_TIMING_FIELDS) {
+        const mappedKey = L2TimingsMap[key] || key;
+        diff[key] = l2Timings[mappedKey];
+      }
+    }
+
+    // Case for testing. We should always try to use l2, but if explicitly requested use L1.
+    if (this.useL1Timings && l1Timings) {
+      diffL1();
+    }
+    else if (l2Timings) {
+      diffL2();
+    }
+    else if (l1Timings) {
+      diffL1();
+    }
 
-      if (timing >= baseTime) {
-        diff[key] = timing - baseTime;
-      } else {
-        diff[key] = null;
+    // We shouldn't see any negative values. If we do something went very wrong.
+    // We will use -11111 as a magic number to ensure a sentry error is captured,
+    // and it's easy to spot.
+    for (const key in NAVIGATION_TIMING_FIELDS) {
+      if (diff[key] < 0) {
+        diff[key] = -11111;
       }
     }
     return diff;