Bug 1633625 - Create a PerfTracker class that monitors the execution and computes performance results. r=jonco
authorSteve Fink <sfink@mozilla.com>
Tue, 19 May 2020 21:55:52 +0000
changeset 530914 37f859f3252ef4b4432723e571961f1be3df59a5
parent 530913 cc9e3394bf4f0b521f5912e07c48b62b62dc198f
child 530915 a57b374c5f80f74a238a20a98787ff13e425736f
push id37434
push userabutkovits@mozilla.com
push dateWed, 20 May 2020 10:05:10 +0000
treeherdermozilla-central@005ef1c25992 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjonco
bugs1633625
milestone78.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1633625 - Create a PerfTracker class that monitors the execution and computes performance results. r=jonco Differential Revision: https://phabricator.services.mozilla.com/D75362
js/src/devtools/gc-ubench/harness.js
js/src/devtools/gc-ubench/perf.js
js/src/devtools/gc-ubench/shell-bench.js
js/src/devtools/gc-ubench/spidermonkey.js
js/src/devtools/gc-ubench/ui.js
js/src/devtools/gc-ubench/v8.js
--- a/js/src/devtools/gc-ubench/harness.js
+++ b/js/src/devtools/gc-ubench/harness.js
@@ -55,16 +55,20 @@ var Host = class {
   }
 
   features = {
     haveMemorySizes: false,
     haveGCCounts: false,
   };
 };
 
+function percent(x) {
+  return `${(x*100).toFixed(2)}%`;
+}
+
 function parse_units(v) {
   if (!v.length) {
     return NaN;
   }
   var lastChar = v[v.length - 1].toLowerCase();
   if (!isNaN(parseFloat(lastChar))) {
     return parseFloat(v);
   }
--- a/js/src/devtools/gc-ubench/perf.js
+++ b/js/src/devtools/gc-ubench/perf.js
@@ -1,14 +1,18 @@
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this file,
  * You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 // Performance monitoring and calculation.
 
+function round_up(val, interval) {
+  return val + (interval - (val % interval));
+}
+
 // Class for inter-frame timing, which handles being paused and resumed.
 var FrameTimer = class {
   constructor() {
     // Start time of the current active test, adjusted for any time spent
     // stopped (so `now - this.start` is how long the current active test
     // has run for.)
     this.start = undefined;
 
@@ -140,8 +144,91 @@ var FrameHistory = class {
   resume() {
     this._frameTimer.resume();
   }
 
   is_stopped() {
     return this._frameTimer.is_stopped();
   }
 };
+
+var PerfTracker = class {
+  constructor() {
+    // Private
+    this._currentLoadStart = undefined;
+    this._frameCount = undefined;
+    this._mutating_ms = undefined;
+    this._suspend_sec = undefined;
+    this._minorGCs = undefined;
+    this._majorGCs = undefined;
+
+    // Public
+    this.results = [];
+  }
+
+  on_load_start(load, now = gHost.now()) {
+    this._currentLoadStart = now;
+    this._frameCount = 0;
+    this._mutating_ms = 0;
+    this._suspend_sec = 0;
+    this._majorGCs = gHost.majorGCCount;
+    this._minorGCs = gHost.minorGCCount;
+  }
+
+  on_load_end(load, now = gHost.now()) {
+    const elapsed_time = (now - this._currentLoadStart) / 1000;
+    const full_time = round_up(elapsed_time, 1 / 60);
+    const frame_60fps_limit = Math.round(full_time * 60);
+    const dropped_60fps_frames = frame_60fps_limit - this._frameCount;
+    const dropped_60fps_fraction = dropped_60fps_frames / frame_60fps_limit;
+
+    const mutating_and_gc_fraction = this._mutating_ms / (full_time * 1000);
+
+    this.results.push({
+      load,
+      elapsed_time,
+      mutating: this._mutating_ms / 1000,
+      mutating_and_gc_fraction,
+      suspended: this._suspend_sec,
+      full_time,
+      frames: this._frameCount,
+      dropped_60fps_frames,
+      dropped_60fps_fraction,
+      majorGCs: gHost.majorGCCount - this._majorGCs,
+      minorGCs: gHost.minorGCCount - this._minorGCs,
+    });
+    this._currentLoadStart = undefined;
+    this._frameCount = 0;
+  }
+
+  after_suspend(wait_sec) {
+    this._suspend_sec += wait_sec;
+  }
+
+  before_mutator(now = gHost.now()) {
+    this._frameCount++;
+  }
+
+  after_mutator(start_time, end_time = gHost.now()) {
+    // Warning: this is called before on_load_start is called from
+    // handle_tick_events.
+  }
+
+  handle_tick_events(events, loadMgr, tick_start, tick_end) {
+    // When the load manager switches from one load to another, there will be
+    // the tick start, the load is switched, the new load runs for a bit, then
+    // the tick end. Associate the timestamp of the start of the tick with both
+    // the end of the previous load and the beginning of the new one.
+    let load_running = true;
+    if (events & loadMgr.LOAD_ENDED) {
+      this.on_load_end(loadMgr.lastActive, tick_start);
+      load_running = false;
+    }
+    if (events & loadMgr.LOAD_STARTED) {
+      this.on_load_start(loadMgr.active, tick_start);
+      load_running = true;
+    }
+
+    if (load_running) {
+      this._mutating_ms += tick_end - tick_start;
+    }
+  }
+};
--- a/js/src/devtools/gc-ubench/shell-bench.js
+++ b/js/src/devtools/gc-ubench/shell-bench.js
@@ -8,28 +8,32 @@ var waited = 0;
 
 // This requires a gHost to have been created that provides host-specific
 // facilities. See eg spidermonkey.js.
 
 loadRelativeToScript("harness.js");
 loadRelativeToScript("perf.js");
 loadRelativeToScript("test_list.js");
 
+var gPerf = new PerfTracker();
+
 var tests = new Map();
 foreach_test_file(f => loadRelativeToScript(f));
 for (const [name, info] of tests.entries()) {
   if ("enabled" in info && !info.enabled) {
     tests.delete(name);
   }
 }
 
 function tick(loadMgr, timestamp) {
+  gPerf.before_mutator(timestamp);
   gHost.start_turn();
   const events = loadMgr.tick(timestamp);
   gHost.end_turn();
+  gPerf.after_mutator(timestamp);
   return events;
 }
 
 function wait_for_next_frame(t0, t1) {
   const elapsed = (t1 - t0) / 1000;
   const period = 1 / FPS;
   const used = elapsed % period;
   const delay = period - used;
@@ -74,18 +78,49 @@ function run(loads) {
 
   let possible = 0;
   let frames = 0;
   while (loadMgr.load_running()) {
     const timestamp = gHost.now();
     perf.on_frame(timestamp);
     const events = tick(loadMgr, timestamp);
     frames++;
+    gPerf.handle_tick_events(events, loadMgr, timestamp, gHost.now());
     if (report_events(events, loadMgr)) {
       possible += (loadMgr.testDurationMS / 1000) * FPS;
       print(
         `  observed ${frames} / ${possible} frames in ${(gHost.now() - t0) /
           1000} seconds`
       );
     }
     wait_for_next_frame(t0, gHost.now());
   }
 }
+
+function report_results() {
+  for (const result of gPerf.results) {
+    const {
+      load,
+      elapsed_time,
+      mutating,
+      mutating_and_gc_fraction,
+      suspended,
+      full_time,
+      frames,
+      dropped_60fps_frames,
+      dropped_60fps_fraction,
+      minorGCs,
+      majorGCs,
+    } = result;
+
+    const drop_pct = percent(dropped_60fps_fraction);
+    const mut_pct = percent(mutating_and_gc_fraction);
+    const mut_sec = mutating.toFixed(2);
+    const full_sec = full_time.toFixed(2);
+    const susp_sec = suspended.toFixed(2);
+    print(`${load.name}:
+  ${frames} (60fps) frames seen out of expected ${Math.floor(full_time * 60)}
+  ${dropped_60fps_frames} = ${drop_pct} 60fps frames dropped
+  ${mut_pct} of run spent mutating and GCing (${mut_sec}sec out of ${full_sec}sec vs ${susp_sec} sec waiting)
+  ${minorGCs} minor GCs, ${majorGCs} major GCs
+`);
+  }
+}
--- a/js/src/devtools/gc-ubench/spidermonkey.js
+++ b/js/src/devtools/gc-ubench/spidermonkey.js
@@ -37,12 +37,21 @@ var SpiderMonkey = class extends Host {
     return performance.mozMemory.gc.zone.gcAllocTrigger;
   }
 
   features = {
     haveMemorySizes: true,
     haveGCCounts: true,
   };
 };
+
 var gHost = new SpiderMonkey();
 
 run(scriptArgs);
 print(`Waited total of ${waited} seconds`);
+print("\nTest results:\n");
+report_results();
+
+var outfile = "spidermonkey-results.json";
+var origOut = redirect(outfile);
+print(JSON.stringify(gPerf.results));
+redirect(origOut);
+print(`Wrote detailed results to ${outfile}`);
--- a/js/src/devtools/gc-ubench/ui.js
+++ b/js/src/devtools/gc-ubench/ui.js
@@ -6,17 +6,17 @@ var stroke = {
   gcslice: "rgb(255,100,0)",
   minor: "rgb(0,255,100)",
   initialMajor: "rgb(180,60,255)",
 };
 
 var numSamples = 500;
 
 var gHistogram = new Map(); // {ms: count}
-var gPerf = new FrameHistory(numSamples);
+var gHistory = new FrameHistory(numSamples);
 
 var latencyGraph;
 var memoryGraph;
 var ctx;
 var memoryCtx;
 
 var loadState = "(init)"; // One of '(active)', '(inactive)', '(N/A)'
 var testState = "idle"; // One of 'idle' or 'running'.
@@ -190,64 +190,64 @@ var LatencyGraph = class extends Graph {
     }
     this.draw60fps();
     this.draw30fps();
 
     var worst = 0,
       worstpos = 0;
     ctx.beginPath();
     for (let i = 0; i < numSamples; i++) {
-      ctx.lineTo(this.xpos(i), this.ypos(gPerf.delays[i]));
-      if (gPerf.delays[i] >= worst) {
-        worst = gPerf.delays[i];
+      ctx.lineTo(this.xpos(i), this.ypos(gHistory.delays[i]));
+      if (gHistory.delays[i] >= worst) {
+        worst = gHistory.delays[i];
         worstpos = i;
       }
     }
     ctx.stroke();
 
     // Draw vertical lines marking minor and major GCs
     if (gHost.features.haveGCCounts) {
       ctx.strokeStyle = stroke.gcslice;
       let idx = sampleIndex % numSamples;
       const count = {
-        major: gPerf.majorGCs[idx],
+        major: gHistory.majorGCs[idx],
         minor: 0,
-        slice: gPerf.slices[idx],
+        slice: gHistory.slices[idx],
       };
       for (let i = 0; i < numSamples; i++) {
         idx = (sampleIndex + i) % numSamples;
-        const isMajorStart = count.major < gPerf.majorGCs[idx];
-        if (count.slice < gPerf.slices[idx]) {
+        const isMajorStart = count.major < gHistory.majorGCs[idx];
+        if (count.slice < gHistory.slices[idx]) {
           if (isMajorStart) {
             ctx.strokeStyle = stroke.initialMajor;
           }
           ctx.beginPath();
           ctx.moveTo(this.xpos(idx), 0);
           ctx.lineTo(this.xpos(idx), this.layout.xAxisLabel_Y);
           ctx.stroke();
           if (isMajorStart) {
             ctx.strokeStyle = stroke.gcslice;
           }
         }
-        count.major = gPerf.majorGCs[idx];
-        count.slice = gPerf.slices[idx];
+        count.major = gHistory.majorGCs[idx];
+        count.slice = gHistory.slices[idx];
       }
 
       ctx.strokeStyle = stroke.minor;
       idx = sampleIndex % numSamples;
-      count.minor = gPerf.minorGCs[idx];
+      count.minor = gHistory.minorGCs[idx];
       for (let i = 0; i < numSamples; i++) {
         idx = (sampleIndex + i) % numSamples;
-        if (count.minor < gPerf.minorGCs[idx]) {
+        if (count.minor < gHistory.minorGCs[idx]) {
           ctx.beginPath();
           ctx.moveTo(this.xpos(idx), 0);
           ctx.lineTo(this.xpos(idx), 20);
           ctx.stroke();
         }
-        count.minor = gPerf.minorGCs[idx];
+        count.minor = gHistory.minorGCs[idx];
       }
     }
 
     ctx.fillStyle = "rgb(255,0,0)";
     if (worst) {
       ctx.fillText(
         `${worst.toFixed(2)}ms`,
         this.xpos(worstpos) - 10,
@@ -255,17 +255,17 @@ var LatencyGraph = class extends Graph {
       );
     }
 
     // Mark and label the slowest frame
     ctx.beginPath();
     var where = sampleIndex % numSamples;
     ctx.arc(
       this.xpos(where),
-      this.ypos(gPerf.delays[where]),
+      this.ypos(gHistory.delays[where]),
       5,
       0,
       Math.PI * 2,
       true
     );
     ctx.fill();
     ctx.fillStyle = "rgb(0,0,0)";
 
@@ -310,22 +310,22 @@ var MemoryGraph = class extends Graph {
     const ctx = this.ctx;
 
     this.clear();
     this.drawFrame();
 
     var worst = 0,
       worstpos = 0;
     for (let i = 0; i < numSamples; i++) {
-      if (gPerf.gcBytes[i] >= worst) {
-        worst = gPerf.gcBytes[i];
+      if (gHistory.gcBytes[i] >= worst) {
+        worst = gHistory.gcBytes[i];
         worstpos = i;
       }
-      if (gPerf.gcBytes[i] < this.bestEver) {
-        this.bestEver = gPerf.gcBytes[i];
+      if (gHistory.gcBytes[i] < this.bestEver) {
+        this.bestEver = gHistory.gcBytes[i];
       }
     }
 
     if (this.worstEver < worst) {
       this.worstEver = worst;
       this.limit = Math.max(this.worstEver, gHost.gcAllocTrigger);
     }
 
@@ -353,62 +353,62 @@ var MemoryGraph = class extends Graph {
         this.ypos(worst) - 14
       );
     }
 
     ctx.beginPath();
     var where = sampleIndex % numSamples;
     ctx.arc(
       this.xpos(where),
-      this.ypos(gPerf.gcBytes[where]),
+      this.ypos(gHistory.gcBytes[where]),
       5,
       0,
       Math.PI * 2,
       true
     );
     ctx.fill();
 
     ctx.beginPath();
     for (let i = 0; i < numSamples; i++) {
       if (i == (sampleIndex + 1) % numSamples) {
-        ctx.moveTo(this.xpos(i), this.ypos(gPerf.gcBytes[i]));
+        ctx.moveTo(this.xpos(i), this.ypos(gHistory.gcBytes[i]));
       } else {
-        ctx.lineTo(this.xpos(i), this.ypos(gPerf.gcBytes[i]));
+        ctx.lineTo(this.xpos(i), this.ypos(gHistory.gcBytes[i]));
       }
       if (i == where) {
         ctx.stroke();
       }
     }
     ctx.stroke();
 
     this.drawAxisLabels("Time", "Heap Memory Usage");
   }
 };
 
 function onUpdateDisplayChanged() {
   const do_graph = document.getElementById("do-graph");
   if (do_graph.checked) {
     window.requestAnimationFrame(handler);
-    gPerf.resume();
+    gHistory.resume();
   } else {
-    gPerf.pause();
+    gHistory.pause();
   }
   update_load_state_indicator();
 }
 
 function onDoLoadChange() {
   const do_load = document.getElementById("do-load");
   gLoadMgr.paused = !do_load.checked;
   console.log(`load paused: ${gLoadMgr.paused}`);
   update_load_state_indicator();
 }
 
 var previous = 0;
 function handler(timestamp) {
-  if (gPerf.is_stopped()) {
+  if (gHistory.is_stopped()) {
     return;
   }
 
   const events = gLoadMgr.tick(timestamp);
   if (events & gLoadMgr.LOAD_ENDED) {
     end_test(timestamp, gLoadMgr.lastActive);
     if (!gLoadMgr.cycleStopped()) {
       start_test();
@@ -416,17 +416,17 @@ function handler(timestamp) {
     update_load_display();
   }
 
   if (testState == "running") {
     document.getElementById("test-progress").textContent =
       (gLoadMgr.currentLoadRemaining(timestamp) / 1000).toFixed(1) + " sec";
   }
 
-  const delay = gPerf.on_frame(timestamp);
+  const delay = gHistory.on_frame(timestamp);
 
   update_histogram(gHistogram, delay);
 
   latencyGraph.draw();
   if (memoryGraph) {
     memoryGraph.draw();
   }
   window.requestAnimationFrame(handler);
@@ -456,17 +456,17 @@ function summarize(arr) {
       prev = arr[i];
     }
   }
 
   return result;
 }
 
 function reset_draw_state() {
-  gPerf.reset();
+  gHistory.reset();
 }
 
 function onunload() {
   gLoadMgr.deactivateLoad();
 }
 
 function onload() {
   // The order of `tests` is currently based on their asynchronous load
@@ -521,17 +521,17 @@ function onload() {
   if (!gHost.features.haveMemorySizes) {
     document.getElementById("memgraph-disabled").style.display = "block";
     document.getElementById("track-sizes-div").style.display = "none";
   }
 
   trackHeapSizes(document.getElementById("track-sizes").checked);
 
   update_load_state_indicator();
-  gPerf.start();
+  gHistory.start();
 
   // Start drawing.
   reset_draw_state();
   window.requestAnimationFrame(handler);
 }
 
 function run_one_test() {
   start_test_cycle([gLoadMgr.activeLoad().name]);
@@ -550,17 +550,17 @@ function start_test_cycle(tests_to_run) 
 }
 
 function update_load_state_indicator() {
   if (
     !gLoadMgr.load_running() ||
     gLoadMgr.activeLoad().name == "noAllocation"
   ) {
     loadState = "(none)";
-  } else if (gPerf.is_stopped() || gLoadMgr.paused) {
+  } else if (gHistory.is_stopped() || gLoadMgr.paused) {
     loadState = "(inactive)";
   } else {
     loadState = "(active)";
   }
   document.getElementById("load-running").textContent = loadState;
 }
 
 function start_test() {
--- a/js/src/devtools/gc-ubench/v8.js
+++ b/js/src/devtools/gc-ubench/v8.js
@@ -30,8 +30,11 @@ var V8 = class extends Host {
   features = {
     haveMemorySizes: false,
     haveGCCounts: false
   };
 };
 
 var gHost = new V8();
 run(arguments);
+
+print("\nTest results:\n");
+report_results();