Fix #3673, instrument response times in shot creation flow (#3727)

addon/webextension/background/analytics.js

@@ -8,6 +8,36 @@ this.analytics = (function() {
   let telemetryPrefKnown = false;
   let telemetryPref;
 
+  function sendTiming(timingLabel, timingVar, timingValue) {
+    // sendTiming is only called in response to sendEvent, so no need to check
+    // the telemetry pref again here.
+    let timingCategory = "addon";
+    return new Promise((resolve, reject) => {
+      let url = main.getBackend() + "/timing";
+      let req = new XMLHttpRequest();
+      req.open("POST", url);
+      req.setRequestHeader("content-type", "application/json");
+      req.onload = catcher.watchFunction(() => {
+        if (req.status >= 300) {
+          let exc = new Error("Bad response from POST /timing");
+          exc.status = req.status;
+          exc.statusText = req.statusText;
+          reject(exc);
+        } else {
+          resolve();
+        }
+      });
+      log.info(`sendTiming ${timingCategory}/${timingLabel}/${timingVar}: ${timingValue}`);
+      req.send(JSON.stringify({
+        deviceId: auth.getDeviceId(),
+        timingCategory,
+        timingLabel,
+        timingVar,
+        timingValue
+      }));
+    });
+  }
+
   exports.sendEvent = function(action, label, options) {
     let eventCategory = "addon";
     if (!telemetryPrefKnown) {
@@ -18,6 +48,12 @@ this.analytics = (function() {
       log.info(`Cancelled sendEvent ${eventCategory}/${action}/${label || 'none'} ${JSON.stringify(options)}`);
       return Promise.resolve();
     }
+    measureTiming(action, label);
+    // Internal-only events are used for measuring time between events,
+    // but aren't submitted to GA.
+    if (action === 'internal') {
+      return Promise.resolve();
+    }
     if (typeof label == "object" && (!options)) {
       options = label;
       label = undefined;
@@ -77,5 +113,107 @@ this.analytics = (function() {
     return !!telemetryPref;
   };
 
+  let timingData = {};
+
+  // Configuration for filtering the sendEvent stream on start/end events.
+  // When start or end events occur, the time is recorded.
+  // When end events occur, the elapsed time is calculated and submitted
+  // via `sendEvent`, where action = "perf-response-time", label = name of rule,
+  // and cd1 value is the elapsed time in milliseconds.
+  // If a cancel event happens between the start and end events, the start time
+  // is deleted.
+  let rules = [{
+    name: 'page-action',
+    start: { action: 'start-shot', label: 'toolbar-button' },
+    end: { action: 'internal', label: 'unhide-preselection-frame' },
+    cancel: [{ action: 'cancel-shot' }]
+  }, {
+    name: 'context-menu',
+    start: { action: 'start-shot', label: 'context-menu' },
+    end: { action: 'internal', label: 'unhide-preselection-frame' },
+    cancel: [{ action: 'cancel-shot' }]
+  }, {
+    name: 'capture-full-page',
+    start: { action: 'capture-full-page' },
+    end: { action: 'internal', label: 'unhide-preview-frame' },
+    cancel: [{ action: 'cancel-shot' }]
+  }, {
+    name: 'capture-visible',
+    start: { action: 'capture-visible' },
+    end: { action: 'internal', label: 'unhide-preview-frame' },
+    cancel: [{ action: 'cancel-shot' }]
+  }, {
+    name: 'make-selection',
+    start: { action: 'make-selection' },
+    end: { action: 'internal', label: 'unhide-selection-frame' },
+    cancel: [{ action: 'cancel-shot' }]
+  }, {
+    name: 'save-shot',
+    start: { action: 'save-shot' },
+    end: { action: 'internal', label: 'open-shot-tab' },
+    cancel: [{ action: 'cancel-shot' }, { action: 'upload-failed' }]
+  }, {
+    name: 'save-visible',
+    start: { action: 'save-visible' },
+    end: { action: 'internal', label: 'open-shot-tab' },
+    cancel: [{ action: 'cancel-shot' }, { action: 'upload-failed' }]
+  }, {
+    name: 'save-full-page',
+    start: { action: 'save-full-page' },
+    end: { action: 'internal', label: 'open-shot-tab' },
+    cancel: [{ action: 'cancel-shot' }, { action: 'upload-failed' }]
+  }, {
+    name: 'save-full-page-truncated',
+    start: { action: 'save-full-page-truncated' },
+    end: { action: 'internal', label: 'open-shot-tab' },
+    cancel: [{ action: 'cancel-shot' }, { action: 'upload-failed' }]
+  }, {
+    name: 'download-shot',
+    start: { action: 'download-shot' },
+    end: { action: 'internal', label: 'deactivate' },
+    cancel: [{ action: 'cancel-shot' }]
+  }, {
+    name: 'download-full-page',
+    start: { action: 'download-full-page' },
+    end: { action: 'internal', label: 'deactivate' },
+    cancel: [{ action: 'cancel-shot' }]
+  }, {
+    name: 'download-full-page-truncated',
+    start: { action: 'download-full-page-truncated' },
+    end: { action: 'internal', label: 'deactivate' },
+    cancel: [{ action: 'cancel-shot' }]
+  }, {
+    name: 'download-visible',
+    start: { action: 'download-visible' },
+    end: { action: 'internal', label: 'deactivate' },
+    cancel: [{ action: 'cancel-shot' }]
+  }];
+
+  // Match a filter (action and optional label) against an action and label.
+  function match(filter, action, label) {
+    return filter.label ?
+      filter.action === action && filter.label === label :
+      filter.action === action;
+  }
+
+  function anyMatches(filters, action, label) {
+    return !!filters.find(filter => match(filter, action, label));
+  }
+
+  function measureTiming(action, label) {
+    rules.forEach(r => {
+      if (anyMatches(r.cancel, action, label)) {
+        delete timingData[r.name];
+      } else if (match(r.start, action, label)) {
+        timingData[r.name] = Date.now();
+      } else if (timingData[r.name] && match(r.end, action, label)) {
+        let endTime = Date.now();
+        let elapsed = endTime - timingData[r.name];
+        catcher.watchPromise(sendTiming("perf-response-time", r.name, elapsed));
+        delete timingData[r.name];
+      }
+    });
+  }
+
   return exports;
 })();

addon/webextension/background/takeshot.js

@@ -57,6 +57,7 @@ this.takeshot = (function() {
       return browser.tabs.create({url: shot.creatingUrl})
     }).then((tab) => {
       openedTab = tab;
+      sendEvent('internal', 'open-shot-tab');
       return uploadShot(shot, imageBlob);
     }).then(() => {
       return browser.tabs.update(openedTab.id, {url: shot.viewUrl}).then(

addon/webextension/selector/ui.js

@@ -184,6 +184,7 @@ this.ui = (function() { // eslint-disable-line no-unused-vars
     unhide() {
       this.updateElementSize();
       this.element.style.display = "";
+      catcher.watchPromise(callBackground("sendEvent", "internal", "unhide-selection-frame"));
       if (highContrastCheck(this.element.contentWindow)) {
         this.element.contentDocument.body.classList.add("hcm");
       }
@@ -349,6 +350,7 @@ this.ui = (function() { // eslint-disable-line no-unused-vars
       window.addEventListener("scroll", watchFunction(assertIsTrusted(this.onScroll)));
       window.addEventListener("resize", this.onResize, true);
       this.element.style.display = "";
+      catcher.watchPromise(callBackground("sendEvent", "internal", "unhide-preselection-frame"));
       if (highContrastCheck(this.element.contentWindow)) {
         this.element.contentDocument.body.classList.add("hcm");
       }
@@ -446,6 +448,7 @@ this.ui = (function() { // eslint-disable-line no-unused-vars
 
     unhide() {
       this.element.style.display = "";
+      catcher.watchPromise(callBackground("sendEvent", "internal", "unhide-preview-frame"));
       this.element.focus();
     },
 

addon/webextension/selector/uicontrol.js

@@ -155,7 +155,7 @@ this.uicontrol = (function() {
       selectedPos = new Selection(
         window.scrollX, window.scrollY,
         window.scrollX + window.innerWidth, window.scrollY + window.innerHeight);
-      captureType = 'visible';
+      captureType = "visible";
       setState("previewing");
     },
     onClickFullPage: () => {
@@ -886,6 +886,7 @@ this.uicontrol = (function() {
 
   exports.deactivate = function() {
     try {
+      sendEvent("internal", "deactivate");
       setState("cancel");
       callBackground('closeSelector');
       selectorLoader.unloadModules();

docs/METRICS.md

@@ -1,6 +1,6 @@
 ## Firefox Screenshots Metrics
 
-*Last Update: 2017-08-17*
+*Last Update: 2017-11-06*
 
 This document is a summary of the metrics Firefox Screenshots will record, how we're recording them, and what we're looking for in those metrics.  There are two main areas we'll look at:
 
@@ -69,7 +69,9 @@ The add-on does not communicate directly with GA, instead it POSTs an event to t
 Each item in these events requires:
 
 Event category: maps to the "source": `addon` or `web`
+
 Event action: what the event "does", such as `start-shot` (note that Save actually "takes" the shot, the focus should be on what happens as a result of interacting with the control)
+
 Event label: exactly what control invoked the action, such as toolbar-button.  These are the "locations":
 
 * `toolbar`: the browser toolbar
@@ -185,6 +187,88 @@ The onboarding slides have some events:
 4. [x] Finish upload successfully `addon/upload/success`
 5. [ ] After failure, re-attempt the upload `addon/upload-retry/times-{N}` (up to version 1.0.1 was `addon/upload/upload-retry` with eventValue: times (1-2)) (FIXME: we have no retry)
 sendEvent("click-install-firefox-home", {useBeacon: true});
+
+#### Add-on performance measurements
+
+Performance measurements use the GA User Timings API, instead of the regular Event API.
+
+##### User Timings schema
+
+Each item in these events requires:
+
+Timing category: maps to the "source": `addon` or `web`
+
+Timing action: what kind of performance measure, currently just `perf-response-time`, which measures the "response" in the RAIL performance model: the time from a user interaction (like a button click) to a user-visible change in the UI.
+
+Timing variable: which event's performance is being measured. This generally is the same as the name of the event used to start the measurement, such as `start-shot`.
+
+Timing value: the number of milliseconds associated with the variable. For `perf-response-time`, the response time in milliseconds.
+
+##### Internal-only events
+
+Internal-only events are used to help measure user timings, but aren't useful to record on their own.
+
+*NOTE: Internal-only events are not submitted to GA.*
+
+1. [x] New tab opened for newly-created shot page `addon/internal/open-shot-tab`
+1. [x] Screenshots UI hidden by uicontrol `addon/internal/deactivate`
+1. [x] Pre-selection iframe shown `addon/internal/unhide-preselection-frame`
+1. [x] Selection iframe shown `addon/internal/unhide-selection-frame`
+1. [x] Preview iframe shown `addon/internal/unhide-preview-frame`
+
+##### First step: starting the shot
+
+1. [x] Time from clicking the page action (or toolbar button) to displaying the preselection iframe, `addon/perf-response-time/page-action`
+  - Start: `addon/start-shot/toolbar-button`
+  - End: `addon/internal/unhide-preselection-frame`
+1. [x] Time from clicking the context menu item to displaying the preselection iframe, `addon/perf-response-time/context-menu`
+  - Start: `addon/start-shot/context-menu`
+  - End: `addon/internal/unhide-preselection-frame`
+
+##### Second step: choosing the shot contents
+
+1. [x] Time from initiating a selection on screen to seeing the selection, `addon/perf-response-time/make-selection`
+  - Start: `addon/make-selection`
+  - End: `addon/internal/unhide-selection-frame`
+1. [x] Time from clicking the 'full page' button to displaying the preview iframe, `addon/perf-response-time/capture-full-page`
+  - Start: `addon/capture-full-page`
+  - End: `addon/internal/unhide-preview-frame`
+1. [x] Time from clicking the 'save visible' button to displaying the preview iframe, `addon/perf-response-time/capture-visible`
+  - Start: `addon/capture-visible`
+  - End: `addon/internal/unhide-preview-frame`
+
+##### Third step: upload or download
+
+For uploads, the measurement is from clicking the save button to a new tab being opened:
+
+1. [x] Save a selection shot (Enter key or button click), `addon/perf-response-time/save-shot`
+  - Start: `addon/save-shot`
+  - End: `addon/internal/open-shot-tab`
+1. [x] Save a full page shot, `addon/perf-response-time/save-full-page`
+  - Start: `addon/save-full-page`
+  - End: `addon/internal/open-shot-tab`
+1. [x] Save a truncated full page shot, `addon/perf-response-time/save-full-page-truncated`
+  - Start: `addon/save-full-page-truncated`
+  - End: `addon/internal/open-shot-tab`
+1. [x] Save a visible selection shot, `addon/perf-response-time/save-visible`
+  - Start: `addon/save-visible`
+  - End: `addon/internal/open-shot-tab`
+
+For downloads, because Firefox doesn't always show download UI, the measurement is from clicking the download button to the screenshots UI being hidden:
+
+1. [x] Download a selection shot, `addon/perf-response-time/download-shot`
+  - Start: `addon/download-shot`
+  - End: `addon/internal/deactivate`
+1. [x] Download a full page shot, `addon/perf-response-time/download-full-page`
+  - Start: `addon/download-full-page`
+  - End: `addon/internal/deactivate`
+1. [x] Download a truncated full page shot, `addon/perf-response-time/download-full-page-truncated`
+  - Start: `addon/download-full-page-truncated`
+  - End: `addon/internal/deactivate`
+1. [x] Download a visible selection shot, `addon/perf-response-time/download-visible`
+  - Start: `addon/download-visible`
+  - End: `addon/internal/deactivate`
+
 #### Owner web visit
 
 These are events that an add-on user can encounter on a shot they own

server/src/middleware/csrf.js

@@ -26,6 +26,7 @@ function isCsrfExemptPath(path) {
   return isAuthPath(path)
     || path.startsWith("/data")
     || path === "/event"
+    || path === "/timing"
     || path === "/error"
     || path === "/api/set-login-cookie";
 }

server/src/server.js

@@ -159,7 +159,7 @@ app.use((req, res, next) => {
 });
 
 function isApiUrl(url) {
-  return url.startsWith("/api") || url === "/event";
+  return url.startsWith("/api") || url === "/event" || url === "/timing";
 }
 
 app.use((req, res, next) => {
@@ -451,6 +451,29 @@ app.post("/event", function(req, res) {
   });
 });
 
+app.post("/timing", function(req, res) {
+  let bodyObj = req.body;
+  if (typeof bodyObj !== "object") {
+    throw new Error(`Got unexpected req.body type: ${typeof bodyObj}`);
+  }
+  hashUserId(req.deviceId).then((userUuid) => {
+    let userAnalytics = ua(config.gaId, userUuid.toString(), {strictCidFormat: false});
+    if (config.debugGoogleAnalytics) {
+      userAnalytics = userAnalytics.debug();
+    }
+    let params = {
+      userTimingCategory: bodyObj.timingCategory,
+      userTimingVariableName: bodyObj.timingVar,
+      userTimingTime: bodyObj.timingValue,
+      userTimingLabel: bodyObj.timingLabel
+    };
+    userAnalytics.timing(params).send();
+    simpleResponse(res, "OK", 200);
+  }).catch((e) => {
+    errorResponse(res, "Error creating user UUID:", e);
+  });
+});
+
 app.post("/api/register", function(req, res) {
   let vars = req.body;
   let canUpdate = vars.deviceId === req.deviceId;