Bug 1622263 - Add Telemetry for about:home startup cache. r=Gijs,data-review=mmccorquodale

Differential Revision: https://phabricator.services.mozilla.com/D81189

browser/components/BrowserGlue.jsm

@@ -4945,6 +4945,7 @@ var AboutHomeStartupCache = {
   // to create the cached document, and then to receive that document.
   CACHE_REQUEST_MESSAGE: "AboutHomeStartupCache:CacheRequest",
   CACHE_RESPONSE_MESSAGE: "AboutHomeStartupCache:CacheResponse",
+  CACHE_USAGE_RESULT_MESSAGE: "AboutHomeStartupCache:UsageResult",
 
   // When a "privileged about content process" is launched, this message is
   // sent to give it some nsIInputStream's for the about:home document they
@@ -4956,6 +4957,27 @@ var AboutHomeStartupCache = {
   // messages as a signal that it's likely time to refresh the cache.
   CACHE_DEBOUNCE_RATE_MS: 5000,
 
+  // The following values are as possible values for the
+  // browser.startup.abouthome_cache_result scalar. Keep these in sync with the
+  // scalar definition in Scalars.yaml. See setDeferredResult for more
+  // information.
+  CACHE_RESULT_SCALARS: {
+    UNSET: 0,
+    DOES_NOT_EXIST: 1,
+    CORRUPT_PAGE: 2,
+    CORRUPT_SCRIPT: 3,
+    INVALIDATED: 4,
+    LATE: 5,
+    VALID_AND_USED: 6,
+    DISABLED: 7,
+    NOT_LOADING_ABOUTHOME: 8,
+    PRELOADING_DISABLED: 9,
+  },
+
+  // This will be set to one of the values of CACHE_RESULT_SCALARS
+  // once it is determined which result best suits what occurred.
+  _cacheDeferredResultScalar: -1,
+
   // A reference to the nsICacheEntry to read from and write to.
   _cacheEntry: null,
 
@@ -4981,9 +5003,12 @@ var AboutHomeStartupCache = {
       throw new Error("AboutHomeStartupCache already initted.");
     }
 
+    this.setDeferredResult(this.CACHE_RESULT_SCALARS.UNSET);
+
     this._enabled = Services.prefs.getBoolPref(this.ENABLED_PREF, false);
 
     if (!this._enabled) {
+      this.recordResult(this.CACHE_RESULT_SCALARS.DISABLED);
       return;
     }
 
@@ -5003,11 +5028,13 @@ var AboutHomeStartupCache = {
 
     if (!willLoadAboutHome) {
       this.log.trace("Not configured to load about:home by default.");
+      this.recordResult(this.CACHE_RESULT_SCALARS.NOT_LOADING_ABOUTHOME);
       return;
     }
 
     if (!Services.prefs.getBoolPref(this.PRELOADED_NEWTAB_PREF, false)) {
       this.log.trace("Preloaded about:newtab disabled.");
+      this.recordResult(this.CACHE_RESULT_SCALARS.PRELOADING_DISABLED);
       return;
     }
 
@@ -5072,6 +5099,7 @@ var AboutHomeStartupCache = {
     this._hasWrittenThisSession = false;
     this._cacheEntryPromise = null;
     this._cacheEntryResolver = null;
+    this._cacheDeferredResultScalar = -1;
 
     this.log.trace("Uninitialized.");
     this.log.removeAppender(this._appender);
@@ -5115,6 +5143,11 @@ var AboutHomeStartupCache = {
       this._cacheTask.arm();
     }
 
+    Services.telemetry.scalarSet(
+      "browser.startup.abouthome_cache_shutdownwrite",
+      this._cacheTask.isArmed
+    );
+
     if (this._cacheTask.isArmed) {
       this.log.trace("Finalizing cache task on shutdown");
       await this._cacheTask.finalize();
@@ -5250,6 +5283,7 @@ var AboutHomeStartupCache = {
         this.log.debug("Cache meta data does not exist. Closing streams.");
         this.pagePipe.outputStream.close();
         this.scriptPipe.outputStream.close();
+        this.setDeferredResult(this.CACHE_RESULT_SCALARS.DOES_NOT_EXIST);
         return;
       }
 
@@ -5264,6 +5298,7 @@ var AboutHomeStartupCache = {
       this.clearCache();
       this.pagePipe.outputStream.close();
       this.scriptPipe.outputStream.close();
+      this.setDeferredResult(this.CACHE_RESULT_SCALARS.INVALIDATED);
       return;
     }
 
@@ -5275,6 +5310,7 @@ var AboutHomeStartupCache = {
       this.log.error("Failed to open main input stream for cache entry", e);
       this.pagePipe.outputStream.close();
       this.scriptPipe.outputStream.close();
+      this.setDeferredResult(this.CACHE_RESULT_SCALARS.CORRUPT_PAGE);
       return;
     }
 
@@ -5304,11 +5340,13 @@ var AboutHomeStartupCache = {
         // to dynamically generating the page.
         this.log.error("Script stream not available! Closing pipe.");
         this.scriptPipe.outputStream.close();
+        this.setDeferredResult(this.CACHE_RESULT_SCALARS.CORRUPT_SCRIPT);
       } else {
         throw e;
       }
     }
 
+    this.setDeferredResult(this.CACHE_RESULT_SCALARS.VALID_AND_USED);
     this.log.trace("Streams connected to pipes. Dropping references to pipes.");
     this._pagePipe = null;
     this._scriptPipe = null;
@@ -5494,6 +5532,7 @@ var AboutHomeStartupCache = {
       );
       this.sendCacheInputStreams(procManager);
       procManager.addMessageListener(this.CACHE_RESPONSE_MESSAGE, this);
+      procManager.addMessageListener(this.CACHE_USAGE_RESULT_MESSAGE, this);
       this._procManager = procManager;
       this._procManagerID = childID;
     }
@@ -5514,6 +5553,10 @@ var AboutHomeStartupCache = {
         this.CACHE_RESPONSE_MESSAGE,
         this
       );
+      this._procManager.removeMessageListener(
+        this.CACHE_USAGE_RESULT_MESSAGE,
+        this
+      );
       this._procManager = null;
       this._procManagerID = null;
     }
@@ -5535,6 +5578,86 @@ var AboutHomeStartupCache = {
     this._cacheTask.arm();
   },
 
+  /**
+   * Stores the CACHE_RESULT_SCALARS value that most accurately represents
+   * the current notion of how the cache has operated so far. It is stored
+   * temporarily like this because we need to hear from the privileged
+   * about content process to hear whether or not retrieving the cache
+   * actually worked on that end. The success state reported back from
+   * the privileged about content process will be compared against the
+   * deferred result scalar to compute what will be recorded to
+   * Telemetry.
+   *
+   * Note that this value will only be recorded if its value is GREATER
+   * than the currently recorded value. This is because it's possible for
+   * certain functions that record results to re-enter - but we want to record
+   * the _first_ condition that caused the cache to not be read from.
+   *
+   * @param result (Number)
+   *   One of the CACHE_RESULT_SCALARS values. If this value is less than
+   *   the currently recorded value, it is ignored.
+   */
+  setDeferredResult(result) {
+    if (this._cacheDeferredResultScalar < result) {
+      this._cacheDeferredResultScalar = result;
+    }
+  },
+
+  /**
+   * Records the final result of how the cache operated for the user
+   * during this session to Telemetry.
+   */
+  recordResult(result) {
+    // Note: this can be called very early on in the lifetime of
+    // AboutHomeStartupCache, so things like this.log might not exist yet.
+    Services.telemetry.scalarSet(
+      "browser.startup.abouthome_cache_result",
+      result
+    );
+  },
+
+  /**
+   * Called when the parent process receives a message from the privileged
+   * about content process saying whether or not reading from the cache
+   * was successful.
+   *
+   * @param success (boolean)
+   *   True if reading from the cache succeeded.
+   */
+  onUsageResult(success) {
+    this.log.trace(`Received usage result. Success = ${success}`);
+    if (success) {
+      if (
+        this._cacheDeferredResultScalar !=
+        this.CACHE_RESULT_SCALARS.VALID_AND_USED
+      ) {
+        this.log.error(
+          "Somehow got a success result despite having never " +
+            "successfully sent down the cache streams"
+        );
+        this.recordResult(this._cacheDeferredResultScalar);
+      } else {
+        this.recordResult(this.CACHE_RESULT_SCALARS.VALID_AND_USED);
+      }
+
+      return;
+    }
+
+    if (
+      this._cacheDeferredResultScalar ==
+      this.CACHE_RESULT_SCALARS.VALID_AND_USED
+    ) {
+      // We failed to read from the cache despite having successfully
+      // sent it down to the content process. We presume then that the
+      // streams just didn't provide any bytes in time.
+      this.recordResult(this.CACHE_RESULT_SCALARS.LATE);
+    } else {
+      // We failed to read the cache, but already knew why. We can
+      // now record that value.
+      this.recordResult(this._cacheDeferredResultScalar);
+    }
+  },
+
   QueryInterface: ChromeUtils.generateQI([
     Ci.nsICacheEntryOpenallback,
     Ci.nsIObserver,
@@ -5551,15 +5674,22 @@ var AboutHomeStartupCache = {
       return;
     }
 
-    if (message.name == this.CACHE_RESPONSE_MESSAGE) {
-      this.log.trace("Parent received cache streams.");
-      if (!this._cacheDeferred) {
-        this.log.error("Parent doesn't have _cacheDeferred set up!");
-        return;
-      }
+    switch (message.name) {
+      case this.CACHE_RESPONSE_MESSAGE: {
+        this.log.trace("Parent received cache streams.");
+        if (!this._cacheDeferred) {
+          this.log.error("Parent doesn't have _cacheDeferred set up!");
+          return;
+        }
 
-      this._cacheDeferred(message.data);
-      this._cacheDeferred = null;
+        this._cacheDeferred(message.data);
+        this._cacheDeferred = null;
+        break;
+      }
+      case this.CACHE_USAGE_RESULT_MESSAGE: {
+        this.onUsageResult(message.data.success);
+        break;
+      }
     }
   },
 

browser/components/newtab/AboutNewTabService.jsm

@@ -88,6 +88,7 @@ const AboutHomeStartupCacheChild = {
   _initted: false,
   CACHE_REQUEST_MESSAGE: "AboutHomeStartupCache:CacheRequest",
   CACHE_RESPONSE_MESSAGE: "AboutHomeStartupCache:CacheResponse",
+  CACHE_USAGE_RESULT_MESSAGE: "AboutHomeStartupCache:UsageResult",
 
   /**
    * Called via a process script very early on in the process lifetime. This
@@ -179,10 +180,12 @@ const AboutHomeStartupCacheChild = {
           !this._scriptInputStream.available() ||
           !this._pageInputStream.available()
         ) {
+          this.reportUsageResult(false /* success */);
           return null;
         }
       } catch (e) {
         if (e.result === Cr.NS_BASE_STREAM_CLOSED) {
+          this.reportUsageResult(false /* success */);
           return null;
         }
         throw e;
@@ -199,6 +202,8 @@ const AboutHomeStartupCacheChild = {
       ? this._scriptInputStream
       : this._pageInputStream;
 
+    this.reportUsageResult(true /* success */);
+
     return channel;
   },
 
@@ -223,7 +228,13 @@ const AboutHomeStartupCacheChild = {
 
     let worker = this.getOrCreateWorker();
 
-    let { page, script } = await worker.post("construct", [state]);
+    TelemetryStopwatch.start("FX_ABOUTHOME_CACHE_CONSTRUCTION");
+
+    let { page, script } = await worker
+      .post("construct", [state])
+      .finally(() => {
+        TelemetryStopwatch.finish("FX_ABOUTHOME_CACHE_CONSTRUCTION");
+      });
 
     let pageInputStream = Cc[
       "@mozilla.org/io/string-input-stream;1"
@@ -259,6 +270,12 @@ const AboutHomeStartupCacheChild = {
       this.constructAndSendCache(state);
     }
   },
+
+  reportUsageResult(success) {
+    Services.cpmm.sendAsyncMessage(this.CACHE_USAGE_RESULT_MESSAGE, {
+      success,
+    });
+  },
 };
 
 /**

browser/components/newtab/test/browser/abouthomecache/browser_bump_version.js

@@ -21,6 +21,9 @@ add_task(async function test_bump_version() {
     );
     cacheEntry.setMetaDataElement("version", "somethingnew");
     await simulateRestart(browser, false /* withAutoShutdownWrite */);
-    await ensureDynamicAboutHome(browser);
+    await ensureDynamicAboutHome(
+      browser,
+      AboutHomeStartupCache.CACHE_RESULT_SCALARS.INVALIDATED
+    );
   });
 });

browser/components/newtab/test/browser/abouthomecache/browser_no_cache.js

@@ -13,6 +13,9 @@ add_task(async function test_no_cache() {
   await BrowserTestUtils.withNewTab("about:home", async browser => {
     await clearCache();
     await simulateRestart(browser, false /* withAutoShutdownWrite */);
-    await ensureDynamicAboutHome(browser);
+    await ensureDynamicAboutHome(
+      browser,
+      AboutHomeStartupCache.CACHE_RESULT_SCALARS.DOES_NOT_EXIST
+    );
   });
 });

browser/components/newtab/test/browser/abouthomecache/head.js

@@ -154,6 +154,23 @@ async function clearCache() {
   info("Test has cleared the cache.");
 }
 
+/**
+ * Checks that the browser.startup.abouthome_cache_result scalar was
+ * recorded at a particular value.
+ *
+ * @param cacheResultScalar (Number)
+ *   One of the AboutHomeStartupCache.CACHE_RESULT_SCALARS values.
+ */
+function assertCacheResultScalar(cacheResultScalar) {
+  let parentScalars = Services.telemetry.getSnapshotForScalars("main").parent;
+  Assert.equal(
+    parentScalars["browser.startup.abouthome_cache_result"],
+    cacheResultScalar,
+    "Expected the right value set to browser.startup.abouthome_cache_result " +
+      "scalar."
+  );
+}
+
 /**
  * Tests that the about:home document loaded in a passed <xul:browser> was
  * one from the cache.
@@ -194,6 +211,9 @@ async function ensureCachedAboutHome(browser) {
       "Should have found the Discovery Stream top sites."
     );
   });
+  assertCacheResultScalar(
+    AboutHomeStartupCache.CACHE_RESULT_SCALARS.VALID_AND_USED
+  );
 }
 
 /**

toolkit/components/telemetry/Histograms.json

@@ -7326,6 +7326,18 @@
     "description": "The length of time (in seconds) that a Picture-in-Picture window was open.",
     "releaseChannelCollection": "opt-out"
   },
+  "FX_ABOUTHOME_CACHE_CONSTRUCTION": {
+    "record_in_processes": ["content"],
+    "products": ["firefox"],
+    "alert_emails": ["mconley@mozilla.com"],
+    "bug_numbers": [1622263],
+    "expires_in_version": "87",
+    "kind": "exponential",
+    "high": 10000,
+    "n_buckets": 100,
+    "description": "The length of time (in milliseconds) that it takes for the cache worker to generate the cache and return it to the main thread",
+    "releaseChannelCollection": "opt-out"
+  },
   "INPUT_EVENT_RESPONSE_MS": {
     "record_in_processes": ["main", "content"],
     "products": ["firefox", "fennec"],

toolkit/components/telemetry/Scalars.yaml

@@ -506,6 +506,52 @@ browser.startup:
     record_in_processes:
       - 'main'
 
+  abouthome_cache_result:
+    bug_numbers:
+      - 1622263
+      - 1614351
+    description: >
+      How the about:home startup cache functioned on startup.
+
+      0: Result value was never set (error case)
+      1: Cache did not exist
+      2: Cache page stream was corrupt / inaccessible
+      3: Cache script stream was corrupt / inaccessible
+      4: Cache was invalidated by a version bump
+      5: Cache was valid, but read too late to be useful.
+      6: Cache was valid and used.
+      7: Cache is disabled.
+      8: User did not load about:home on its own by default.
+      9: Cache is disabled because about:newtab preloading is disabled.
+
+    expires: "87"
+    kind: uint
+    notification_emails:
+      - mconley@mozilla.com
+    release_channel_collection: opt-out
+    products:
+      - 'firefox'
+    record_in_processes:
+      - 'main'
+
+  abouthome_cache_shutdownwrite:
+    bug_numbers:
+      - 1622263
+      - 1614351
+    description: >
+      True if the about:home startup cache was written via the AsyncShutdown
+      blocker.
+
+    expires: "87"
+    kind: boolean
+    notification_emails:
+      - mconley@mozilla.com
+    release_channel_collection: opt-out
+    products:
+      - 'firefox'
+    record_in_processes:
+      - 'main'
+
 # The following section contains the browser usage scalars.
 browser.usage:
   graphite: