Bug 1899749 - Use profiler markers for getting performance data r=dom-worker-reviewers,smaug,profiler-reviewers,aabh,asuth,perftest-reviewers,sparky

Use profiler markers to collect timing data.  Markers of known name:

  AUTO_PROFILER_MARKER_TEXT("interesting thing #1", DOM, {}, ""_ns);
  AUTO_PROFILER_MARKER_TEXT("interesting thing #2", DOM, {}, ""_ns);

can be inspected from the perftest:

  await startProfiler();
  interestingThings();
  let pdata = await stopProfiler();
  let duration_ms = inspectProfile(pdata, [
      "interesting thing #1",
      "interesting thing #2"
  ]);

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

dom/docs/workersAndStorage/PerformanceTesting.rst

@@ -41,6 +41,28 @@ There's currently a `bug <https://bugzilla.mozilla.org/show_bug.cgi?id=1872613>`
 which will likely cause the command to fail.  Running it a second time should
 succeed.
 
+Profiler Markers
+================
+
+Profiler markers can be used to collect timing data.  Markers of known name can be inspected from the perftest.  AUTO_PROFILER_MARKER_TEXT must be used, as we need both the start-time and end-time of the marker.  For example:
+
+.. code-block:: cpp
+
+ AUTO_PROFILER_MARKER_TEXT("interesting thing #1", DOM, {}, ""_ns);
+ AUTO_PROFILER_MARKER_TEXT("interesting thing #2", DOM, {}, ""_ns);
+
+can be inspected from the perftest:
+
+.. code-block:: js
+
+ await startProfiler();
+ interestingThings();
+ let pdata = await stopProfiler();
+ let duration_ms = inspectProfile(pdata, [
+     "interesting thing #1",
+     "interesting thing #2"
+ ]);
+
 Staging tests in try jobs
 =========================
 
@@ -66,5 +88,5 @@ These symbol names are defined in the .yml files under taskcluster/kinds/perftes
 
 Contacts
 ========
-| `Joshua Marshall <https://people.mozilla.org/p/jmarshall>`_   (DOM LWS)
+| DOM LWS
 | `Gregory Mierzwinski <https://people.mozilla.org/p/sparky>`_  (Performance Tools)

dom/serviceworkers/ServiceWorkerActors.cpp

@@ -13,6 +13,7 @@
 #include "ServiceWorkerRegistrationChild.h"
 #include "ServiceWorkerRegistrationParent.h"
 #include "mozilla/dom/WorkerRef.h"
+#include "mozilla/ProfilerMarkers.h"
 
 namespace mozilla::dom {
 
@@ -30,6 +31,8 @@ void InitServiceWorkerContainerParent(PServiceWorkerContainerParent* aActor) {
 void InitServiceWorkerRegistrationParent(
     PServiceWorkerRegistrationParent* aActor,
     const IPCServiceWorkerRegistrationDescriptor& aDescriptor) {
+  AUTO_PROFILER_MARKER_TEXT("InitServiceWorkerRegistrationParent", DOM, {},
+                            ""_ns);
   auto actor = static_cast<ServiceWorkerRegistrationParent*>(aActor);
   actor->Init(aDescriptor);
 }

dom/serviceworkers/ServiceWorkerContainer.cpp

@@ -200,6 +200,8 @@ already_AddRefed<nsIURI> GetBaseURIFromGlobal(nsIGlobalObject* aGlobal,
 already_AddRefed<Promise> ServiceWorkerContainer::Register(
     const nsAString& aScriptURL, const RegistrationOptions& aOptions,
     const CallerType aCallerType, ErrorResult& aRv) {
+  AUTO_PROFILER_MARKER_TEXT("SWC Register", DOM, {}, ""_ns);
+
   // Note, we can't use GetGlobalIfValid() from the start here.  If we
   // hit a storage failure we want to log a message with the final
   // scope string we put together below.
@@ -375,6 +377,8 @@ already_AddRefed<Promise> ServiceWorkerContainer::Register(
       [self,
        outer](const IPCServiceWorkerRegistrationDescriptorOrCopyableErrorResult&
                   aResult) {
+        AUTO_PROFILER_MARKER_TEXT("SWC Register (inner)", DOM, {}, ""_ns);
+
         if (aResult.type() ==
             IPCServiceWorkerRegistrationDescriptorOrCopyableErrorResult::
                 TCopyableErrorResult) {

dom/serviceworkers/ServiceWorkerManager.cpp

@@ -834,6 +834,8 @@ ServiceWorkerManager::RegisterForTest(nsIPrincipal* aPrincipal,
 RefPtr<ServiceWorkerRegistrationPromise> ServiceWorkerManager::Register(
     const ClientInfo& aClientInfo, const nsACString& aScopeURL,
     const nsACString& aScriptURL, ServiceWorkerUpdateViaCache aUpdateViaCache) {
+  AUTO_PROFILER_MARKER_TEXT("SWM Register", DOM, {}, ""_ns);
+
   nsCOMPtr<nsIURI> scopeURI;
   nsresult rv = NS_NewURI(getter_AddRefs(scopeURI), aScopeURL);
   if (NS_FAILED(rv)) {

dom/serviceworkers/ServiceWorkerRegisterJob.cpp

@@ -8,6 +8,7 @@
 
 #include "mozilla/dom/WorkerCommon.h"
 #include "ServiceWorkerManager.h"
+#include "mozilla/ProfilerMarkers.h"
 
 namespace mozilla::dom {
 
@@ -20,6 +21,8 @@ ServiceWorkerRegisterJob::ServiceWorkerRegisterJob(
 void ServiceWorkerRegisterJob::AsyncExecute() {
   MOZ_ASSERT(NS_IsMainThread());
 
+  AUTO_PROFILER_MARKER_TEXT("SWRJ AsyncExecute", DOM, {}, ""_ns);
+
   RefPtr<ServiceWorkerManager> swm = ServiceWorkerManager::GetInstance();
   if (Canceled() || !swm) {
     FailUpdateJob(NS_ERROR_DOM_ABORT_ERR);

dom/serviceworkers/test/performance/perftest.toml

@@ -10,5 +10,8 @@ support-files = [
 ]
 
 ["test_caching.html"]
+
 ["test_fetch.html"]
+
 ["test_registration.html"]
+skip-if = ["tsan"] # 1885378

dom/serviceworkers/test/performance/perfutils.js

@@ -1,5 +1,9 @@
 "use strict";
 
+const formatNumber = new Intl.NumberFormat("en-US", {
+  maximumSignificantDigits: 4,
+}).format;
+
 /**
  * Given a map from test names to arrays of results, report perfherder metrics
  * and log full results.
@@ -14,7 +18,7 @@ function reportMetrics(journal) {
   for (const name in journal) {
     const med = median(journal[name]);
     text += (name + ":").padEnd(prefixLen, " ") + stringify(journal[name]);
-    text += "   median " + med + "\n";
+    text += "   median " + formatNumber(med) + "\n";
     metrics[name] = med;
   }
 
@@ -34,13 +38,95 @@ function median(arr) {
 }
 
 function stringify(arr) {
-  function pad(num) {
-    let s = num.toString().padStart(5, " ");
-    if (s[0] != " ") {
-      s = " " + s;
+  function pad(str) {
+    str = str.padStart(7, " ");
+    if (str[0] != " ") {
+      str = " " + str;
     }
-    return s;
+    return str;
   }
 
-  return arr.reduce((acc, elem) => acc + pad(elem), "");
+  return arr.reduce((acc, elem) => acc + pad(formatNumber(elem)), "");
+}
+
+async function startProfiler() {
+  let script = SpecialPowers.loadChromeScript(async () => {
+    // See profiler doc via: $ MOZ_PROFILER_HELP=1 ./mach run
+    const settings = {
+      features: ["nomarkerstacks", "nostacksampling"],
+      threads: ["GeckoMain", "IPDL Background"],
+    };
+
+    await Services.profiler.StartProfiler(
+      settings.entries,
+      settings.interval,
+      settings.features,
+      settings.threads
+    );
+
+    sendAsyncMessage("started");
+  });
+
+  return script.promiseOneMessage("started");
+}
+
+/**
+ * Returns profiler data
+ * https://github.com/firefox-devtools/profiler/blob/main/docs-developer/gecko-profile-format.md
+ */
+async function stopProfiler() {
+  let script = SpecialPowers.loadChromeScript(async () => {
+    Services.profiler.getProfileDataAsync().then(profileData => {
+      Services.profiler.StopProfiler();
+      sendAsyncMessage("done", profileData);
+    });
+  });
+
+  return script.promiseOneMessage("done");
+}
+
+/**
+ * Look through profiler results for markers with name in names.
+ * Return the cumulative duration in ms.
+ */
+function inspectProfile(pdata, names) {
+  let unseen = new Set(names);
+  let duration = inspectProfileInternal(pdata, new Set(unseen), unseen);
+  // Error if we fail to see each name at least once
+  is(
+    unseen.size,
+    0,
+    `${unseen.size} missing markers ` +
+      [...unseen].join(", ") +
+      " (If this fails, check threads of interest in settings.threads)"
+  );
+  return duration;
+}
+
+function inspectProfileInternal(pdata, names, unseen) {
+  let duration = 0;
+
+  for (let thread of pdata.threads) {
+    const nameIdx = thread.markers.schema.name;
+    const startTimeIdx = thread.markers.schema.startTime;
+    const endTimeIdx = thread.markers.schema.endTime;
+
+    for (let m of thread.markers.data) {
+      let markerName = thread.stringTable[m[nameIdx]];
+
+      if (names.has(markerName)) {
+        let d = m[endTimeIdx] - m[startTimeIdx];
+        duration += d;
+        info(`marker ${markerName}: ${formatNumber(d)} ms`);
+        unseen.delete(markerName);
+      }
+    }
+  }
+
+  for (let process of pdata.processes) {
+    // Look for markers in child processes
+    duration += inspectProfileInternal(process, names, unseen);
+  }
+
+  return duration;
 }

dom/serviceworkers/test/performance/test_registration.html

@@ -10,16 +10,24 @@
 
   "use strict";
 
+  // "Total" register() time, including process startup.  We don't cause it all,
+  // but we're affected by it.
   const REGISTRATION = "Registration";
+
+  // Targeted timing of regristration machinery.
+  const REGISTRATION_INTERNALS = "Registration Internals";
+
   const ACTIVATION = "Activation";
+
   const UNREGISTRATION = "Unregistration";
 
-  var journal = [];
+  var journal = {};
   journal[REGISTRATION] = [];
+  journal[REGISTRATION_INTERNALS] = [];
   journal[ACTIVATION] = [];
   journal[UNREGISTRATION] = [];
 
-  const ITERATIONS = 10;
+  const ITERATIONS = 11;
 
   var perfMetadata = {
     owner: "DOM LWS",
@@ -32,6 +40,7 @@
           // Here, we can't use the constants defined above because perfherder
           // grabs data from the parse tree.
           { name: "Registration", unit: "ms", shouldAlert: true },
+          { name: "Registration Internals", unit: "ms", shouldAlert: true },
           { name: "Activation", unit: "ms", shouldAlert: true },
           { name: "Unregistration", unit: "ms", shouldAlert: true },
         ],
@@ -42,21 +51,14 @@
     },
   };
 
-  function create_iframe(url) {
-    return new Promise(function(res) {
-      let iframe = document.createElement("iframe");
-      iframe.src = url;
-      iframe.onload = function() { res(iframe) }
-      document.body.appendChild(iframe);
-    });
-  }
-
   add_task(async () => {
     await SpecialPowers.pushPrefEnv({
       set: [["dom.serviceWorkers.testing.enabled", true]]
     });
 
     async function measure() {
+      await startProfiler();
+
       let begin_ts = performance.now();
       let reg = await navigator.serviceWorker.register("sw_empty.js");
       let reg_ts = performance.now();
@@ -65,7 +67,17 @@
       await reg.unregister();
       let unreg_ts = performance.now();
 
+      let pdata = await stopProfiler();
+      let duration_ms = inspectProfile(pdata, [
+        "SWM Register",
+        "SWRJ AsyncExecute",
+        "InitServiceWorkerRegistrationParent",
+        "SWC Register",
+        "SWC Register (inner)"
+      ]);
+
       journal[REGISTRATION].push(reg_ts - begin_ts);
+      journal[REGISTRATION_INTERNALS].push(duration_ms);
       journal[ACTIVATION].push(act_ts - reg_ts);
       journal[UNREGISTRATION].push(unreg_ts - act_ts);
     }

testing/perfdocs/generated/mozperftest.rst

@@ -77,7 +77,7 @@ test_registration.html
 ::
 
  --perfherder
- --perfherder-metrics name:Registration,unit:ms,shouldAlert:True, name:Activation,unit:ms,shouldAlert:True, name:Unregistration,unit:ms,shouldAlert:True
+ --perfherder-metrics name:Registration,unit:ms,shouldAlert:True, name:Registration Internals,unit:ms,shouldAlert:True, name:Activation,unit:ms,shouldAlert:True, name:Unregistration,unit:ms,shouldAlert:True
  --verbose
  --manifest perftest.toml
  --manifest-flavor plain