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
+  this._startTime = this._speedTrap.baseTime;
-  // navigationTiming.navigationStart, otherwise Date.now().
-  this._startTime = options.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,16 @@ _.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()) {
+      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,23 @@ 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 +56,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 +75,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 +86,9 @@ describe('lib/metrics', () => {
           xhr,
         })
       );
+
+      // Peak at start time.
+      startTime = metrics._startTime;
       sinon.spy(metrics, '_initializeSubscriptionModel');
     }
 
@@ -330,7 +345,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 +1136,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,67 +2,109 @@
  * 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 = {
+import {NAVIGATION_TIMING_FIELDS, OPTIONAL_NAVIGATION_TIMING_FIELDS} from './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;
+const L2TimingsMap = {
-try {
+  'navigationStart': 'startTime',
-  // eslint-disable-next-line no-undef
+  'domLoading': 'domContentLoadedEventStart'
-  navigationTiming = window.performance.timing;
-} catch (e) {
-  // NOOP
 }
 
-if (!navigationTiming) {
+const TimingVersions = {
-  navigationTiming = Object.create(NAVIGATION_TIMING_FIELDS);
+  L2: 'L2',
+  L1: 'L1',
+  UNKNOWN: ''
 }
 
-var navigationStart = navigationTiming.navigationStart || Date.now();
-
 class NavigationTiming {
-  init(options) {
+  init(opts) {
-    options = options || {};
+
-    this.navigationTiming = options.navigationTiming || navigationTiming;
+    // A performance api must be provided
-    this.baseTime = navigationStart;
+    if (!opts || !opts.performance) {
+      throw new Error('opts.performance is required!')
+    }
+    this.performance = opts.performance;
+    this.useL1Timings = opts.useL1Timings;
   }
 
-  get() {
+  getTimingVersion () {
-    return this.navigationTiming;
+    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) {
+    // If we are using our fallback performance api (ie window.performance
-      var timing = this.navigationTiming[key];
+    // doesn't  exist), don't return anything.
+    if (this.performance.unreliable === true) {
+      return undefined;
+    }
 
-      if (timing >= baseTime) {
+    const diff = {}
-        diff[key] = timing - baseTime;
+    const l2Timings = this.getL2Timings();
-      } else {
+    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();
+    }
+
+    // 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;
   }

packages/fxa-shared/speed-trap/performance-factory.js

@@ -0,0 +1,88 @@
+/* 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/. */
+
+import { NAVIGATION_TIMING_FIELDS } from './timing-fields'
+
+/**
+ * Small util for determining if a browser went to sleep.
+ */
+class SleepDetection {
+
+  constructor() {
+    this.sleepDetected = false;
+    this.lastTime =Date.now();
+    this.iid = '';
+  }
+
+  startSleepDetection() {
+    this.iid = setInterval(() => {
+       if (this.sleepDetected) {
+         clearInterval(this.iid);
+         return;
+       }
+
+       const currentTime = Date.now();
+       if (currentTime > (this.lastTime + 2000*2)) {  // ignore small delays
+         this.sleepDetected = true;
+       }
+       this.lastTime = currentTime;
+     }, 2000);
+   }
+}
+
+/**
+ * This minimal fallback api is deemed unreliable. We use this in
+ * the event a browser doesn't provide a performance api. In these
+ * cases there is not a monotonic clock for us to rely on, which can
+ * result in weird edge cases where a system is put into a sleep state
+ * and the metrics collected will be wildly off.
+ */
+class PerformanceFallback {
+
+  constructor() {
+    this.unreliable = true;
+    this.timeOrigin = Date.now();
+    this.timing = Object.create(NAVIGATION_TIMING_FIELDS);
+    this.sleepDetection = new SleepDetection();
+    this.sleepDetection.startSleepDetection();
+  }
+
+  now() {
+    return Date.now() - this.timeOrigin;
+  }
+
+  // If the machine was put to sleep during metrics collection, the values
+  // are invalid and cannot be used.
+  isInSuspectState() {
+    return this.sleepDetection.sleepDetected;
+  }
+}
+
+/**
+ * Provides a fake performance api with minimal functionality.
+ */
+export function getFallbackPerformanceApi() {
+  return new PerformanceFallback();
+}
+
+/**
+ * Provides the browser's performance api.
+ */
+export function getRealPerformanceApi () {
+  // eslint-disable-next-line no-undef
+  return window.performance;
+}
+
+/**
+ * Provides a performance api, or for browsers that don't support the performance api, a version
+ * of it to support minimal functionality required by speed trap.
+ */
+export function getPerformanceApi() {
+  // eslint-disable-next-line no-undef
+  if (!!window.performance && typeof window.performance.now === 'function') {
+    return getRealPerformanceApi();
+  }
+
+  return getFallbackPerformanceApi();
+}

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

@@ -5,24 +5,29 @@ import guid from './guid';
 import NavigationTiming from './navigation-timing';
 import Timers from './timers';
 import Events from './events';
+import { getPerformanceApi } from './performance-factory';
 
 var SpeedTrap = {
   init: function (options) {
     options = options || {};
-    this.navigationTiming = Object.create(NavigationTiming);
-    this.navigationTiming.init(options);
 
-    this.baseTime = this.navigationTiming.get().navigationStart || Date.now();
+    // This will provide the browser's performance API, or a fallback version which has
+    // reduced functionality. The exact performance API can also be passed in as option
+    // for testing purposes.
+    this.performance = options.performance || getPerformanceApi();
+    this.baseTime = this.performance.timeOrigin;
+
+    this.navigationTiming = Object.create(NavigationTiming);
+    this.navigationTiming.init({
+      performance: this.performance,
+      useL1Timings: options.useL1Timings
+    });
 
     this.timers = Object.create(Timers);
-    this.timers.init({
+    this.timers.init({performance: this.performance});
-      baseTime: this.baseTime,
-    });
 
     this.events = Object.create(Events);
-    this.events.init({
+    this.events.init({performance: this.performance});
-      baseTime: this.baseTime,
-    });
 
     this.uuid = guid();
 
@@ -59,10 +64,12 @@ var SpeedTrap = {
       // if cookies are disabled, sessionStorage access will blow up.
     }
 
+    const navigationTiming = this.navigationTiming.diff();
+
     return {
       uuid: this.uuid,
       puuid: previousPageUUID,
-      navigationTiming: this.navigationTiming.diff(),
+      navigationTiming,
       // eslint-disable-next-line no-undef
       referrer: document.referrer || '',
       tags: this.tags,
@@ -92,11 +99,43 @@ var SpeedTrap = {
 
     return {
       uuid: this.uuid,
-      duration: Date.now() - this.baseTime,
+      // The performance API keeps track of the current duration. The exact way this is done
+      // may vary depending on the browser's implementation. We will assume that as long as we
+      // stay within the confines of the browser's implementation, this value is reasonable.
+      // What is not reasonable is assuming the that we can Subtract Date.now() from
+      // performance.timeOrigin or performance.timings.navigationStart and get a valid value.
+      // It's very likely the performance API is using a monotonic clock that does not match our
+      // current system clock.
+      duration: this.performance.now(),
       timers: this.timers.get(),
       events: this.events.get(),
     };
   },
+
+  /**
+   * Return the current time using speed trap's clock. If the performance api is available
+   * its monotonic clock will be used. Otherwise the system clock is used (ie Date.now()).
+   *
+   * Note: The system clock is susceptible to edge cases were a machine sleeps during a load
+   * operation. In this case we may result produce a very large metric.
+   *
+   * Note: performance.now() will likely differ from Date.now() and is not expected to be the real
+   * time. Please be aware of what underlying implementation is in use when calling this function.
+   */
+  now: function() {
+    return this.performance.timeOrigin + this.performance.now();
+  },
+
+  /**
+   * Legacy browsers can end up in suspect states when a machine is put into sleep mode during
+   * metrics collection. This flag indicates the machine is likely in an invalid state.
+   */
+  isInSuspectState: function () {
+    if (this.performance.unreliable === true) {
+      return this.performance.isInSuspectState();
+    }
+    return false;
+  }
 };
 
 export default Object.create(SpeedTrap);

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

@@ -4,22 +4,31 @@
 
 class Timers {
   init(options) {
+    if (!options || !options.performance) {
+      throw new Error('options.performance required')
+    }
+
     this.completed = {};
     this.running = {};
-    this.baseTime = options.baseTime;
+    this.performance = options.performance;
+    this.baseTime = options.performance.timeOrigin;
   }
 
   start(name) {
-    var start = Date.now();
+    var start = this.performance.now()
-    if (this.running[name]) throw new Error(name + ' timer already started');
+    if (typeof this.running[name] === 'number') {
+      throw new Error(name + ' timer already started');
+    }
 
     this.running[name] = start;
   }
 
   stop(name) {
-    var stop = Date.now();
+    var stop = this.performance.now()
 
-    if (!this.running[name]) throw new Error(name + ' timer not started');
+    if (typeof this.running[name] !== 'number') {
+      throw new Error(name + ' timer not started');
+    }
 
     if (!this.completed[name]) this.completed[name] = [];
     var start = this.running[name];

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

@@ -0,0 +1,40 @@
+/* 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/. */
+
+ /**
+  * Navigation Timing fields we use for metrics.
+  */
+export 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,
+};
+
+export const OPTIONAL_NAVIGATION_TIMING_FIELDS = [
+  'loadEventEnd',
+  'loadEventStart',
+  'redirectEnd',
+  'redirectStart',
+  'secureConnectionStart',
+  'unloadEventEnd',
+  'unloadEventStart'
+];