Bug 1360916 - Update telemetry code in sessionstore content script r=mikedeboer data-r=bsmedberg

This patch replaces FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS with
a more fine-grained data collection via a keyed histogram so that we can
determine which type of data collection we spend a lot of time on.

Additionally, it abandons sending telemetry data from the content to the parent
via custom messages and instead uses the Telemetry service directly. Thus it
also gets rid of a bug that currently overrides measurements for the same
histogram done quickly in succession

browser/components/sessionstore/SessionStore.jsm

@@ -858,9 +858,8 @@ var SessionStoreInternal = {
           return;
         }
 
-        // Record telemetry measurements done in the child and update the tab's
-        // cached state. Mark the window as dirty and trigger a delayed write.
-        this.recordTelemetry(aMessage.data.telemetry);
+        // Update the tab's cached state.
+        // Mark the window as dirty and trigger a delayed write.
         TabState.update(browser, aMessage.data);
         this.saveStateDelayed(win);
 
@@ -973,7 +972,6 @@ var SessionStoreInternal = {
         this._crashedBrowsers.delete(browser.permanentKey);
         break;
       case "SessionStore:error":
-        this.reportInternalError(data);
         TabStateFlusher.resolveAll(browser, false, "Received error from the content process");
         break;
       default:
@@ -981,18 +979,6 @@ var SessionStoreInternal = {
     }
   },
 
-  /**
-   * Record telemetry measurements stored in an object.
-   * @param telemetry
-   *        {histogramID: value, ...} An object mapping histogramIDs to the
-   *        value to be recorded for that ID,
-   */
-  recordTelemetry(telemetry) {
-    for (let histogramId in telemetry) {
-      Telemetry.getHistogramById(histogramId).add(telemetry[histogramId]);
-    }
-  },
-
   /* ........ Window Event Handlers .............. */
 
   /**
@@ -4734,19 +4720,6 @@ var SessionStoreInternal = {
     this._browserEpochs.delete(browser.permanentKey);
   },
 
-  /**
-   * Handle an error report from a content process.
-   */
-  reportInternalError(data) {
-    // For the moment, we only report errors through Telemetry.
-    if (data.telemetry) {
-      for (let key of Object.keys(data.telemetry)) {
-        let histogram = Telemetry.getHistogramById(key);
-        histogram.add(data.telemetry[key]);
-      }
-    }
-  },
-
   /**
    * Countdown for a given duration, skipping beats if the computer is too busy,
    * sleeping or otherwise unavailable.

browser/components/sessionstore/content/content-sessionStore.js

@@ -15,6 +15,9 @@ Cu.import("resource://gre/modules/XPCOMUtils.jsm", this);
 Cu.import("resource://gre/modules/Timer.jsm", this);
 Cu.import("resource://gre/modules/Services.jsm", this);
 
+XPCOMUtils.defineLazyModuleGetter(this, "TelemetryStopwatch",
+  "resource://gre/modules/TelemetryStopwatch.jsm");
+
 function debug(msg) {
   Services.console.logStringMessage("SessionStoreContent: " + msg);
 }
@@ -657,8 +660,8 @@ var SessionStorageListener = {
         }
 
         let size = this.estimateStorageSize(collected);
+        Services.telemetry.getHistogramById("FX_SESSION_RESTORE_DOM_STORAGE_SIZE_ESTIMATE_CHARS").add(size);
 
-        MessageQueue.push("telemetry", () => ({ FX_SESSION_RESTORE_DOM_STORAGE_SIZE_ESTIMATE_CHARS: size }));
         if (size > Preferences.get("browser.sessionstore.dom_storage_limit", DOM_STORAGE_MAX_CHARS)) {
           // Rather than keeping the old storage, which wouldn't match the rest
           // of the state of the page, empty the storage. DOM storage will be
@@ -826,42 +829,39 @@ var MessageQueue = {
     }
 
     let flushID = (options && options.flushID) || 0;
-
-    let durationMs = Date.now();
+    let histID = "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_MS";
 
     let data = {};
-    let telemetry = {};
     for (let [key, func] of this._data) {
+      if (key != "isPrivate") {
+        TelemetryStopwatch.startKeyed(histID, key);
+      }
+
       let value = func();
-      if (key == "telemetry") {
-        for (let histogramId of Object.keys(value)) {
-          telemetry[histogramId] = value[histogramId];
-        }
-      } else if (value || (key != "storagechange" && key != "historychange")) {
+
+      if (key != "isPrivate") {
+        TelemetryStopwatch.finishKeyed(histID, key);
+      }
+
+      if (value || (key != "storagechange" && key != "historychange")) {
         data[key] = value;
       }
     }
 
     this._data.clear();
 
-    durationMs = Date.now() - durationMs;
-    telemetry.FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS = durationMs;
-
     try {
       // Send all data to the parent process.
       sendAsyncMessage("SessionStore:update", {
-        data, telemetry, flushID,
+        data, flushID,
         isFinal: options.isFinal || false,
         epoch: gCurrentEpoch
       });
     } catch (ex) {
-        if (ex && ex.result == Cr.NS_ERROR_OUT_OF_MEMORY) {
-          sendAsyncMessage("SessionStore:error", {
-            telemetry: {
-              FX_SESSION_RESTORE_SEND_UPDATE_CAUSED_OOM: 1
-            }
-          });
-        }
+      if (ex && ex.result == Cr.NS_ERROR_OUT_OF_MEMORY) {
+        Services.telemetry.getHistogramById("FX_SESSION_RESTORE_SEND_UPDATE_CAUSED_OOM").add(1);
+        sendAsyncMessage("SessionStore:error");
+      }
     }
   },
 };

browser/components/sessionstore/test/browser_sessionStorage_size.js

@@ -13,18 +13,23 @@ const OUTER_VALUE = "outer-value-" + RAND;
 // Test that we record the size of messages.
 add_task(function* test_telemetry() {
   Services.telemetry.canRecordExtended = true;
-  let histogram = Services.telemetry.getHistogramById("FX_SESSION_RESTORE_DOM_STORAGE_SIZE_ESTIMATE_CHARS");
+  let histogram = Services.telemetry.getHistogramById("FX_SESSION_RESTORE_DOM_STORAGE_SIZE_ESTIMATE_CHARS#content");
   let snap1 = histogram.snapshot();
 
   let tab = gBrowser.addTab(URL);
   let browser = tab.linkedBrowser;
   yield promiseBrowserLoaded(browser);
 
-  // Flush to make sure chrome received all data.
+  // Flush to make sure we submitted telemetry data.
   yield TabStateFlusher.flush(browser);
-  let snap2 = histogram.snapshot();
 
-  Assert.ok(snap2.counts[5] > snap1.counts[5]);
+  // There is no good way to make sure that the parent received the histogram entries from the child processes.
+  // Let's stick to the ugly, spinning the event loop until we have a good approach (Bug 1357509).
+  yield BrowserTestUtils.waitForCondition(() => {
+    return histogram.snapshot().counts[5] > snap1.counts[5];
+  });
+
+  Assert.ok(true);
   yield promiseRemoveTab(tab);
   Services.telemetry.canRecordExtended = false;
 });

toolkit/components/telemetry/Histograms.json

@@ -5664,13 +5664,15 @@
     "n_buckets": 10,
     "description": "Session restore: Time to collect all window and tab data (ms)"
   },
-  "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS": {
-    "alert_emails": ["session-restore-telemetry-alerts@mozilla.com"],
-    "expires_in_version": "default",
+  "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_MS": {
+    "alert_emails": ["session-restore-telemetry-alerts@mozilla.com", "mdeboer@mozilla.com"],
+    "expires_in_version": "60",
     "kind": "exponential",
+    "keyed": true,
     "high": 30000,
-    "n_buckets": 10,
-    "description": "Session restore: Duration of the longest uninterruptible operation while collecting data in the content process (ms)"
+    "n_buckets": 20,
+    "bug_numbers": [1360916],
+    "description": "Session restore: Duration of data collection in the content process (ms). Possible keys currently are: historychange, scroll, formdata, pageStyle, disallow, storage, storagechange."
   },
   "FX_SESSION_RESTORE_PRIVACY_LEVEL": {
     "alert_emails": ["session-restore-telemetry-alerts@mozilla.com"],

toolkit/components/telemetry/histogram-whitelists.json

@@ -941,7 +941,6 @@
     "FX_SESSION_RESTORE_AUTO_RESTORE_DURATION_UNTIL_EAGER_TABS_RESTORED_MS",
     "FX_SESSION_RESTORE_COLLECT_ALL_WINDOWS_DATA_MS",
     "FX_SESSION_RESTORE_COLLECT_DATA_MS",
-    "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS",
     "FX_SESSION_RESTORE_CORRUPT_FILE",
     "FX_SESSION_RESTORE_DOM_STORAGE_SIZE_ESTIMATE_CHARS",
     "FX_SESSION_RESTORE_FILE_SIZE_BYTES",
@@ -1750,7 +1749,6 @@
     "MOZ_SQLITE_OTHER_READ_B",
     "CHECK_JAVA_ENABLED",
     "TRANSLATION_OPPORTUNITIES",
-    "FX_SESSION_RESTORE_CONTENT_COLLECT_DATA_LONGEST_OP_MS",
     "NEWTAB_PAGE_BLOCKED_SITES_COUNT",
     "FX_SESSION_RESTORE_NUMBER_OF_TABS_RESTORED",
     "WEAVE_START_COUNT",