Bug 1680766 - Improvements to profile markers for Talos tests; r=perftest-reviewers,gregtatum,sparky

This patch is to add more profile markers to Talos tests, and improve existing ones, by grouping all Talos markers together under "Talos", using more descriptive labels, and employing interval markers where applicable.

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

testing/talos/talos/pageloader/chrome/pageloader.js

@@ -724,7 +724,8 @@ function _loadHandlerCapturing() {
 
   if (gTime !== -1) {
     plRecordTime(gTime);
-    TalosParentProfiler.pause("capturing load handler fired");
+    TalosParentProfiler.mark("Talos - capturing load handler fired");
+    TalosParentProfiler.pause();
     gTime = -1;
     recordedName = null;
     setTimeout(plNextPage, delay);

testing/talos/talos/talos-powers/api.js

@@ -35,6 +35,7 @@ Cu.importGlobalProperties(["TextEncoder"]);
 const Cm = Components.manager.QueryInterface(Ci.nsIComponentRegistrar);
 
 let frameScriptURL;
+let profilerStartTime;
 
 function TalosPowersService() {
   this.wrappedJSObject = this;
@@ -175,9 +176,8 @@ TalosPowersService.prototype = {
    */
   profilerPause(marker = null) {
     if (marker) {
-      ChromeUtils.addProfilerMarker(marker);
+      this.addIntervalMarker(marker, profilerStartTime);
     }
-
     Services.profiler.PauseSampling();
   },
 
@@ -191,16 +191,35 @@ TalosPowersService.prototype = {
   profilerResume(marker = null) {
     Services.profiler.ResumeSampling();
 
+    profilerStartTime = Cu.now();
+
     if (marker) {
-      ChromeUtils.addProfilerMarker(marker);
+      this.addInstantMarker(marker);
     }
   },
 
   /**
-   * Adds a marker to the Profile in the parent process.
+   * Adds an instant marker to the Profile in the parent process.
+   *
+   * @param marker (string)  A marker to set.
+   *
    */
-  profilerMarker(marker) {
-    ChromeUtils.addProfilerMarker(marker);
+  addInstantMarker(marker) {
+    ChromeUtils.addProfilerMarker("Talos", undefined, marker);
+  },
+
+  /**
+   * Adds a marker to the Profile in the parent process.
+   *
+   * @param marker (string)
+   *        A marker to set before pausing.
+   *
+   * @param startTime (number)
+   *        Start time, used to create an interval profile marker. If
+   *        undefined, a single instance marker will be placed.
+   */
+  addIntervalMarker(marker, startTime) {
+    ChromeUtils.addProfilerMarker("Talos", startTime, marker);
   },
 
   receiveProfileCommand(message) {
@@ -229,7 +248,7 @@ TalosPowersService.prototype = {
       }
 
       case "Profiler:Pause": {
-        this.profilerPause(data.marker);
+        this.profilerPause(data.marker, data.startTime);
         mm.sendAsyncMessage(ACK_NAME, { name });
         break;
       }
@@ -241,8 +260,9 @@ TalosPowersService.prototype = {
       }
 
       case "Profiler:Marker": {
-        this.profilerMarker(data.marker);
+        this.profilerMarker(data.marker, data.startTime);
         mm.sendAsyncMessage(ACK_NAME, { name });
+        break;
       }
     }
   },

testing/talos/talos/talos-powers/content/TalosContentProfiler.js

@@ -232,7 +232,7 @@ var TalosContentProfiler;
      *        for us, and we can skip the initialization check. This is usually
      *        true for pageloader tests.
      * @returns Promise
-     *          Resolves once the Gecko Profiler has resumed.
+     *        Resolves once the Gecko Profiler has resumed.
      */
     resume(marker = "", inittedInParent = false) {
       if (initted || inittedInParent) {
@@ -250,12 +250,15 @@ var TalosContentProfiler;
      *        If true, it is assumed that the parent has already started profiling
      *        for us, and we can skip the initialization check. This is usually
      *        true for pageloader tests.
+     * @param startTime (number, optional)
+     *        Start time, used to create an interval profile marker. If
+     *        undefined, a single instance marker will be placed.
      * @returns Promise
-     *          Resolves once the Gecko Profiler has paused.
+     *        Resolves once the Gecko Profiler has paused.
      */
-    pause(marker = "", inittedInParent = false) {
+    pause(marker = "", inittedInParent = false, startTime = undefined) {
       if (initted || inittedInParent) {
-        return sendEventAndWait("Profiler:Pause", { marker });
+        return sendEventAndWait("Profiler:Pause", { marker, startTime });
       }
 
       return Promise.resolve();
@@ -264,17 +267,26 @@ var TalosContentProfiler;
     /**
      * Adds a marker to the profile.
      *
+     * @param marker (string)
+     *        If non-empty, will set a marker immediately before pausing.
+     * @param inittedInParent (bool, optional)
+     *        If true, it is assumed that the parent has already started profiling
+     *        for us, and we can skip the initialization check. This is usually
+     *        true for pageloader tests.
+     * @param startTime (number, optional)
+     *        Start time, used to create an interval profile marker. If
+     *        undefined, a single instance marker will be placed.
      * @returns Promise
      *          Resolves once the marker has been set.
      */
-    mark(marker) {
-      if (initted) {
+    mark(marker, inittedInParent = false, startTime = undefined) {
+      if (initted || inittedInParent) {
         // If marker is omitted, just use the test name
         if (!marker) {
           marker = currentTest;
         }
 
-        return sendEventAndWait("Profiler:Marker", { marker });
+        return sendEventAndWait("Profiler:Marker", { marker, startTime });
       }
 
       return Promise.resolve();

testing/talos/talos/talos-powers/content/TalosParentProfiler.jsm

@@ -185,29 +185,39 @@ const TalosParentProfiler = {
   /**
    * Pauses the Gecko Profiler sampler. Can also simultaneously set a marker.
    *
+   * @param marker (string, optional)
+   *        If non-empty, will set a marker immediately before pausing.
+   * @param startTime (number, optional)
+   *        Start time, used to create an interval profile marker. If
+   *        undefined, a single instance marker will be placed.
    * @returns Promise
-   *          Resolves once the Gecko Profiler has paused.
+   *          Resolves once the Gecko Profiler has resumed.
    */
-  pause(marker = "") {
+  pause(marker = "", startTime = undefined) {
     if (this.initted) {
-      this.TalosPowers.profilerPause(marker);
+      this.TalosPowers.profilerPause(marker, startTime);
     }
   },
 
   /**
    * Adds a marker to the profile.
    *
+   * @param marker (string, optional)
+   *        If non-empty, will set a marker immediately before pausing.
+   * @param startTime (number, optional)
+   *        Start time, used to create an interval profile marker. If
+   *        undefined, a single instance marker will be placed.
    * @returns Promise
    *          Resolves once the marker has been set.
    */
-  mark(marker) {
+  mark(marker, startTime = undefined) {
     if (this.initted) {
       // If marker is omitted, just use the test name
       if (!marker) {
         marker = this.currentTest;
       }
 
-      this.TalosPowers.profilerMarker(marker);
+      this.TalosPowers.addIntervalMarker(marker, startTime);
     }
   },
 

testing/talos/talos/tests/a11y/dhtml.html

@@ -8,6 +8,7 @@
   /* globals initAccessibility */
   // based on: http://hacks.mozilla.org/2010/05/better-performance-with-lazy-frame-construction/
   var ppDate = null;
+  var startTime;
 
   function doInsertion() {
     if (!initAccessibility()) {
@@ -15,10 +16,12 @@
       return;
     }
 
-    TalosContentProfiler.resume("dhtml test start", true).then(() => {
+    TalosContentProfiler.resume("a11y: Begin dhtml test", true).then(() => {
       var container = document.getElementById("container");
       var lastchild = document.getElementById("lastchild");
-      var start = window.performance.now();
+
+      startTime = window.performance.now();
+
       var i, div;
       for (i = 0; i < 2000; i++) {
         div = document.createElement("div");
@@ -39,15 +42,14 @@
         container.appendChild(div);
       }
       document.documentElement.offsetLeft; // flush layout
-      setTimeout(postProcessingRecord, 0, start);
+      setTimeout(postProcessingRecord, 0, startTime);
     });
   }
 
-  function postProcessingRecord(s) {
-    // alert(window.performance.now() - s);
-    let delta = window.performance.now() - s;
-    TalosContentProfiler.pause("dhtml test finish", true).then(() => {
-      tpRecordTime(delta, window.performance.timing.navigationStart + s);
+  function postProcessingRecord(start) {
+    let delta = window.performance.now() - start;
+    TalosContentProfiler.pause("a11y: dhtml test", true, startTime).then(() => {
+      tpRecordTime(delta, window.performance.timing.navigationStart + start);
     });
   }
 </script>

testing/talos/talos/tests/a11y/tablemutation.html

@@ -82,11 +82,14 @@ window.onload = function() {
     mutateTable();
   }, 100);
 };
+
+
 function mutateTable() {
   var htmTable = document.getElementById("datatable");
   var TableRows = [ ];
 
   // Locate all TR elements of the table
+  TalosContentProfiler.mark('a11yr tablemutation - locate all TR elements of the table', true)
   var htmRow = htmTable.childNodes[0];
   while (htmRow) {
     if (htmRow.nodeType == 1) {
@@ -104,6 +107,7 @@ function mutateTable() {
   Range.setEndAfter(TableRows[TableRows.length - 1]);
 
   // Put all rows into a Fragment
+  TalosContentProfiler.mark('a11yr tablemutation - put all rows into a fragment', true)
   var Fragment = document.createDocumentFragment();
   for (var Index in TableRows) {
     Fragment.appendChild(TableRows[Index]);
@@ -118,23 +122,20 @@ function mutateTable() {
   ensureAccessibleTreeForId("start");
 
   TalosContentProfiler.resume("tablemutation start", true).then(() => {
-    var start = window.performance.now();
-
     // Cause all kinds of crazy events
     Range.deleteContents();
     Range.insertNode(Fragment);
 
     document.documentElement.offsetLeft; // flush layout
 
-    setTimeout(postProcessingRecord, 0, start);
+    setTimeout(postProcessingRecord, 0);
   });
 }
 
-function postProcessingRecord(s) {
-  // alert(window.performance.now() - s);
-  let delta = window.performance.now() - s;
-  TalosContentProfiler.pause("tablemutation finish", true).then(() => {
-    tpRecordTime(delta, window.performance.timing.navigationStart + s);
+function postProcessingRecord(startTime) {
+  let delta = window.performance.now() - startTime;
+  TalosContentProfiler.pause("a11y test: tablemutation", true).then(() => {
+    tpRecordTime(delta, window.performance.timing.navigationStart + startTime);
   });
 }
 </script>

testing/talos/talos/tests/cpstartup/extension/api.js

@@ -98,7 +98,9 @@ this.cpstartup = class extends ExtensionAPI {
 
   async openTab(gBrowser, url) {
     // Start the timer and the profiler right before the tab open on the parent side.
-    TalosParentProfiler.resume("tab opening starts");
+    TalosParentProfiler.resume("cpstartup: Begin Tab Open");
+    let startTime = Cu.now();
+
     this.startStamp = Services.telemetry.msSystemNow();
     let newDomainURL = url.replace(
       /http:\/\/127\.0\.0\.1:[0-9]+/,
@@ -107,7 +109,7 @@ this.cpstartup = class extends ExtensionAPI {
     this.tab = gBrowser.selectedTab = gBrowser.addTrustedTab(newDomainURL);
 
     let { tab, delta } = await this.whenTabReady();
-    TalosParentProfiler.pause("tab opening end");
+    TalosParentProfiler.pause("cpstartup: Tab Open", startTime);
     await this.removeTab(tab);
     return delta;
   }

testing/talos/talos/tests/gfx/benchmarks/rasterflood_gradient.html

@@ -74,6 +74,8 @@ function runFrame() {
     return;
   }
 
+  TalosContentProfiler.mark("rasterflood_gradient", true, start);
+
   window.requestAnimationFrame(runFrame);
 }
 
@@ -109,6 +111,7 @@ addEventListener("load", function() {
       startTest();
     });
   } catch (e) {
+    TalosContentProfiler.resume("rasterflood_gradient.html loaded", true);
     startTest();
   }
 });

testing/talos/talos/tests/gfx/benchmarks/rasterflood_svg.html

@@ -123,6 +123,7 @@ function runFrame() {
 
   window.requestAnimationFrame(runFrame);
   gIterations++;
+  TalosContentProfiler.mark("rasterflood svg", gStart);
 }
 
 function startTest() {

testing/talos/talos/tests/tabpaint/api.js

@@ -134,7 +134,9 @@ this.tabpaint = class extends ExtensionAPI {
    */
   async openTabFromParent(gBrowser, target) {
     let win = BrowserWindowTracker.getTopWindow();
-    TalosParentProfiler.resume("tabpaint parent start");
+
+    TalosParentProfiler.resume("TabPaint Parent Start");
+    let startTime = Cu.now();
 
     gBrowser.selectedTab = gBrowser.addTab(
       //win.performance.now() + win.performance.timing.navigationStart gives the UNIX timestamp.
@@ -146,7 +148,10 @@ this.tabpaint = class extends ExtensionAPI {
     );
 
     let { tab, delta } = await this.whenTabShown();
-    TalosParentProfiler.pause("tabpaint parent end");
+    TalosParentProfiler.pause(
+      "Talos - Tabpaint: Open Tab from Parent",
+      startTime
+    );
     await this.removeTab(tab);
     return delta;
   }
@@ -163,12 +168,16 @@ this.tabpaint = class extends ExtensionAPI {
    *         with the time (in ms) it took to open the tab from content.
    */
   async openTabFromContent(gBrowser) {
-    TalosParentProfiler.resume("tabpaint content start");
+    TalosParentProfiler.resume("TabPaint Content Start");
+    let start_time = Cu.now();
 
     Services.mm.broadcastAsyncMessage("TabPaint:OpenFromContent");
 
     let { tab, delta } = await this.whenTabShown();
-    TalosParentProfiler.pause("tabpaint content end");
+    TalosParentProfiler.pause(
+      "Talos - Tabpaint: Open Tab from Content",
+      start_time
+    );
     await this.removeTab(tab);
     return delta;
   }
@@ -195,6 +204,7 @@ this.tabpaint = class extends ExtensionAPI {
    * @return Promise
    */
   removeTab(tab) {
+    TalosParentProfiler.mark("Tabpaint: Remove Tab");
     return new Promise(resolve => {
       let { messageManager: mm, frameLoader } = tab.linkedBrowser;
       mm.addMessageListener(

testing/talos/talos/tests/tabswitch/api.js

@@ -283,9 +283,11 @@ async function test(window) {
     await new Promise(resolve => Services.tm.dispatchToMainThread(resolve));
 
     await forceGC(win, tab.linkedBrowser);
-    TalosParentProfiler.resume("start: " + tab.linkedBrowser.currentURI.spec);
+    TalosParentProfiler.resume();
     let time = await switchToTab(tab);
-    TalosParentProfiler.pause("finish: " + tab.linkedBrowser.currentURI.spec);
+    TalosParentProfiler.pause(
+      "TabSwitch Test: " + tab.linkedBrowser.currentURI.spec
+    );
     dump(`${tab.linkedBrowser.currentURI.spec}: ${time}ms\n`);
     times.push(time);
     await switchToTab(initialTab);