Bug 1364235 - Collect telemetry stats on startup cache hits and misses r=kmag

In bug 1264235 we have some indication that observed bugs with the
startup cache might have been resolved, but we don't really know
until we collect data. Collecting these stats will give us the
ability to have more certainty that the startup cache is functioning
correctly in the wild.

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

--HG--
extra : moz-landing-system : lando

js/xpconnect/loader/ScriptPreloader.cpp

@@ -899,12 +899,23 @@ JSScript* ScriptPreloader::GetCachedScript(JSContext* cx,
   // If a script is used by both the parent and the child, it's stored only
   // in the child cache.
   if (mChildCache) {
-    auto script = mChildCache->GetCachedScript(cx, path);
+    RootedScript script(cx, mChildCache->GetCachedScriptInternal(cx, path));
     if (script) {
+      Telemetry::AccumulateCategorical(
+          Telemetry::LABELS_SCRIPT_PRELOADER_REQUESTS::HitChild);
       return script;
     }
   }
 
+  RootedScript script(cx, GetCachedScriptInternal(cx, path));
+  Telemetry::AccumulateCategorical(
+      script ? Telemetry::LABELS_SCRIPT_PRELOADER_REQUESTS::Hit
+             : Telemetry::LABELS_SCRIPT_PRELOADER_REQUESTS::Miss);
+  return script;
+}
+
+JSScript* ScriptPreloader::GetCachedScriptInternal(JSContext* cx,
+                                                   const nsCString& path) {
   auto script = mScripts.Get(path);
   if (script) {
     return WaitForCachedScript(cx, script);
@@ -939,6 +950,8 @@ JSScript* ScriptPreloader::WaitForCachedScript(JSContext* cx,
       LOG(Info, "Script is small enough to recompile on main thread\n");
 
       script->mReadyToExecute = true;
+      Telemetry::ScalarAdd(
+          Telemetry::ScalarID::SCRIPT_PRELOADER_MAINTHREAD_RECOMPILE, 1);
     } else {
       while (!script->mReadyToExecute) {
         mal.Wait();
@@ -948,7 +961,9 @@ JSScript* ScriptPreloader::WaitForCachedScript(JSContext* cx,
       }
     }
 
-    LOG(Debug, "Waited %fms\n", (TimeStamp::Now() - start).ToMilliseconds());
+    double waitedMS = (TimeStamp::Now() - start).ToMilliseconds();
+    Telemetry::Accumulate(Telemetry::SCRIPT_PRELOADER_WAIT_TIME, int(waitedMS));
+    LOG(Debug, "Waited %fms\n", waitedMS);
   }
 
   return script->GetJSScript(cx);

js/xpconnect/loader/ScriptPreloader.h

@@ -103,6 +103,7 @@ class ScriptPreloader : public nsIObserver,
 
  private:
   Result<Ok, nsresult> InitCacheInternal(JS::HandleObject scope = nullptr);
+  JSScript* GetCachedScriptInternal(JSContext* cx, const nsCString& name);
 
  public:
   void Trace(JSTracer* trc);

startupcache/StartupCache.cpp

@@ -13,6 +13,7 @@
 #include "nsAutoPtr.h"
 #include "nsClassHashtable.h"
 #include "nsComponentManagerUtils.h"
+#include "nsCRT.h"
 #include "nsDirectoryServiceUtils.h"
 #include "nsIClassInfo.h"
 #include "nsIFile.h"
@@ -261,12 +262,21 @@ nsresult StartupCache::GetBuffer(const char* id, UniquePtr<char[]>* outbuf,
       *outbuf = MakeUnique<char[]>(entry->size);
       memcpy(outbuf->get(), entry->data.get(), entry->size);
       *length = entry->size;
+      Telemetry::AccumulateCategorical(
+          Telemetry::LABELS_STARTUP_CACHE_REQUESTS::HitMemory);
       return NS_OK;
     }
   }
 
   nsresult rv = GetBufferFromZipArchive(mArchive, true, id, outbuf, length);
-  if (NS_SUCCEEDED(rv)) return rv;
+  if (NS_SUCCEEDED(rv)) {
+    Telemetry::AccumulateCategorical(
+        Telemetry::LABELS_STARTUP_CACHE_REQUESTS::HitDisk);
+    return rv;
+  }
+
+  Telemetry::AccumulateCategorical(
+      Telemetry::LABELS_STARTUP_CACHE_REQUESTS::Miss);
 
   RefPtr<nsZipArchive> omnijar =
       mozilla::Omnijar::GetReader(mozilla::Omnijar::APP);
@@ -422,7 +432,14 @@ void StartupCache::WriteToDisk() {
   LoadArchive();
 }
 
-void StartupCache::InvalidateCache() {
+void StartupCache::InvalidateCache(bool memoryOnly) {
+  if (memoryOnly) {
+    // The memoryOnly option is just for testing purposes. We want to ensure
+    // that we're nuking the in-memory form but that we preserve everything
+    // on disk.
+    WriteToDisk();
+    return;
+  }
   WaitOnWriteThread();
   mPendingWrites.Clear();
   mTable.Clear();
@@ -506,7 +523,7 @@ nsresult StartupCacheListener::Observe(nsISupports* subject, const char* topic,
     sc->WaitOnWriteThread();
     StartupCache::gShutdownInitiated = true;
   } else if (strcmp(topic, "startupcache-invalidate") == 0) {
-    sc->InvalidateCache();
+    sc->InvalidateCache(data && nsCRT::strcmp(data, u"memoryOnly") == 0);
   }
   return NS_OK;
 }

startupcache/StartupCache.h

@@ -118,7 +118,7 @@ class StartupCache : public nsIMemoryReporter {
                      uint32_t length);
 
   // Removes the cache file.
-  void InvalidateCache();
+  void InvalidateCache(bool memoryOnly = false);
 
   // Signal that data should not be loaded from the cache file
   static void IgnoreDiskCache();

startupcache/moz.build

@@ -8,6 +8,7 @@ with Files("**"):
     BUG_COMPONENT = ("Core", "XPCOM")
 
 TEST_DIRS += ['test']
+BROWSER_CHROME_MANIFESTS += ['test/browser.ini']
 
 EXPORTS.mozilla.scache += [
     'StartupCache.h',

startupcache/test/browser.ini

@@ -0,0 +1 @@
+[browser_startupcache_telemetry.js]

startupcache/test/browser_startupcache_telemetry.js

@@ -0,0 +1,40 @@
+/* Any copyright is dedicated to the Public Domain.
+   http://creativecommons.org/publicdomain/zero/1.0/ */
+
+"use strict";
+
+const LABELS_STARTUP_CACHE_REQUESTS = {
+  HitMemory: 0,
+  HitDisk: 1,
+  Miss: 2,
+};
+
+add_task(async function() {
+  Services.obs.notifyObservers(null, "startupcache-invalidate");
+  Services.telemetry.getSnapshotForHistograms("main", true);
+  let newWin = await BrowserTestUtils.openNewBrowserWindow();
+  let snapshot = Services.telemetry.getSnapshotForHistograms("main", true);
+  function histValue(label) {
+    return snapshot.parent.STARTUP_CACHE_REQUESTS.values[label] || 0;
+  }
+  Assert.equal(histValue(LABELS_STARTUP_CACHE_REQUESTS.HitMemory), 0);
+  Assert.equal(histValue(LABELS_STARTUP_CACHE_REQUESTS.HitDisk), 0);
+  Assert.notEqual(histValue(LABELS_STARTUP_CACHE_REQUESTS.Miss), 0);
+  await BrowserTestUtils.closeWindow(newWin);
+
+  newWin = await BrowserTestUtils.openNewBrowserWindow();
+  snapshot = Services.telemetry.getSnapshotForHistograms("main", true);
+  Assert.notEqual(histValue(LABELS_STARTUP_CACHE_REQUESTS.HitMemory), 0);
+  Assert.equal(histValue(LABELS_STARTUP_CACHE_REQUESTS.HitDisk), 0);
+  Assert.notEqual(histValue(LABELS_STARTUP_CACHE_REQUESTS.Miss), 0);
+  await BrowserTestUtils.closeWindow(newWin);
+
+  Services.obs.notifyObservers(null, "startupcache-invalidate", "memoryOnly");
+  newWin = await BrowserTestUtils.openNewBrowserWindow();
+  snapshot = Services.telemetry.getSnapshotForHistograms("main", true);
+  Assert.notEqual(histValue(LABELS_STARTUP_CACHE_REQUESTS.HitMemory), 0);
+  Assert.notEqual(histValue(LABELS_STARTUP_CACHE_REQUESTS.HitDisk), 0);
+  // Some misses can come through - just ensure it's a small number
+  Assert.ok(histValue(LABELS_STARTUP_CACHE_REQUESTS.Miss) < 5);
+  await BrowserTestUtils.closeWindow(newWin);
+});

testing/marionette/harness/marionette_harness/tests/unit/test_startup_caches.py

@@ -0,0 +1,80 @@
+# Any copyright is dedicated to the Public Domain.
+# http://creativecommons.org/publicdomain/zero/1.0/
+
+from __future__ import absolute_import
+
+import time
+import os
+from marionette_harness import MarionetteTestCase
+
+LABELS_SCRIPT_PRELOADER_REQUESTS = {
+  "Hit": "0",
+  "HitChild": "1",
+  "Miss": "2",
+}
+
+
+class TestScriptPreloader(MarionetteTestCase):
+    def test_preloader_requests_histogram(self):
+        start_time = time.time()
+        self.invalidate_caches()
+        self.marionette.restart(clean=False, in_app=True)
+        histogram = self.get_histogram("SCRIPT_PRELOADER_REQUESTS")
+        misses = histogram.get(LABELS_SCRIPT_PRELOADER_REQUESTS["Miss"], 0)
+        hits = histogram.get(LABELS_SCRIPT_PRELOADER_REQUESTS["Hit"], 0)
+        child_hits = histogram.get(LABELS_SCRIPT_PRELOADER_REQUESTS["HitChild"], 0)
+        self.assertMuchGreaterThan(misses, hits)
+        self.assertMuchGreaterThan(misses, child_hits)
+
+        profile = self.marionette.profile_path
+        self.wait_for_file_change(start_time, "{}/startupCache/scriptCache.bin".format(profile))
+        self.wait_for_file_change(start_time, "{}/startupCache/scriptCache-child.bin".format(profile))
+        self.marionette.restart(clean=False, in_app=True)
+        histogram = self.get_histogram("SCRIPT_PRELOADER_REQUESTS")
+        misses = histogram.get(LABELS_SCRIPT_PRELOADER_REQUESTS["Miss"], 0)
+        hits = histogram.get(LABELS_SCRIPT_PRELOADER_REQUESTS["Hit"], 0)
+        child_hits = histogram.get(LABELS_SCRIPT_PRELOADER_REQUESTS["HitChild"], 0)
+        # This is just heuristic. We certainly want to be made aware if this ratio
+        # changes and we didn't intend it to.
+        self.assertSimilar(misses, hits)
+        self.assertNotEqual(child_hits, 0)
+
+    def assertMuchGreaterThan(self, lhs, rhs):
+        self.assertTrue(lhs > 4 * rhs)
+
+    def assertSimilar(self, lhs, rhs):
+        self.assertTrue(lhs < 2 * rhs)
+        self.assertTrue(lhs > rhs / 2)
+
+    def wait_for_file_change(self, start_time, path):
+        expires = time.time() + 20
+        while True:
+            try:
+                if os.stat(path).st_mtime > start_time:
+                    return
+                if time.time() > expires:
+                    raise Error("Never observed file change for {}".format(path))
+                time.sleep(1)
+            except OSError:
+                pass
+
+
+    def wait_for_observer_notification(self, name):
+        with self.marionette.using_context(self.marionette.CONTEXT_CHROME):
+            return self.marionette.execute_script("""
+                let [resolve] = arguments;
+                Services.obs.addObserver(() => resolve(), "{}");
+            """.format(name))
+
+    def get_histogram(self, name):
+        with self.marionette.using_context(self.marionette.CONTEXT_CHROME):
+            return self.marionette.execute_script("""
+                let snapshot = Services.telemetry.getSnapshotForHistograms("main", true);
+                return snapshot.parent.{}.values;
+            """.format(name))
+
+    def invalidate_caches(self):
+        with self.marionette.using_context(self.marionette.CONTEXT_CHROME):
+            return self.marionette.execute_script(
+                "Services.obs.notifyObservers(null, 'startupcache-invalidate');"
+            )

testing/marionette/harness/marionette_harness/tests/unit/unit-tests.ini

@@ -129,3 +129,6 @@ skip-if = asan || manage_instance == false || appname == 'fennec' # Bug 1298921
 
 [test_reftest.py]
 skip-if = appname == 'fennec' # Bug 1519552
+
+[test_startup_caches.py]
+skip-if = appname == 'fennec'

toolkit/components/telemetry/Histograms.json

@@ -4680,6 +4680,37 @@
     "kind": "boolean",
     "description": "mozStorage async requests success *** No longer needed (bug 1156565). Delete histogram and accumulation code! ***"
   },
+  "STARTUP_CACHE_REQUESTS": {
+    "record_in_processes": ["main"],
+    "alert_emails": ["dothayer@mozilla.com"],
+    "expires_in_version": "73",
+    "kind": "categorical",
+    "labels": ["HitMemory", "HitDisk", "Miss"],
+    "bug_numbers": [1364235],
+    "releaseChannelCollection": "opt-out",
+    "description": "Record hits and misses to the startup cache, with categories."
+  },
+  "SCRIPT_PRELOADER_REQUESTS": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["dothayer@mozilla.com"],
+    "expires_in_version": "73",
+    "kind": "categorical",
+    "labels": ["Hit", "HitChild", "Miss"],
+    "bug_numbers": [1364235],
+    "releaseChannelCollection": "opt-out",
+    "description": "Record hits and misses to the script preloader, with categories."
+  },
+  "SCRIPT_PRELOADER_WAIT_TIME": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["dothayer@mozilla.com"],
+    "expires_in_version": "73",
+    "kind": "exponential",
+    "high": 10000,
+    "n_buckets": 20,
+    "bug_numbers": [1364235],
+    "releaseChannelCollection": "opt-out",
+    "description": "Time spent waiting for off-thread compiles in the script preloader."
+  },
   "STARTUP_MEASUREMENT_ERRORS": {
     "record_in_processes": ["main", "content"],
     "expires_in_version": "default",

toolkit/components/telemetry/Scalars.yaml

@@ -2495,6 +2495,23 @@ startup:
     record_in_processes:
       - main
 
+script.preloader:
+  mainthread_recompile:
+    bug_numbers:
+      - 1364235
+    description:
+      How many times we ended up recompiling a script from the script preloader
+      on the main thread.
+    expires: "73"
+    keyed: false
+    kind: uint
+    notification_emails:
+      - dothayer@mozilla.com
+    release_channel_collection: opt-out
+    record_in_processes:
+      - 'main'
+      - 'content'
+
 # The following section is for probes testing the Telemetry system. They will not be
 # submitted in pings and are only used for testing.
 telemetry.test: