Bug 1370659 - Add more measurements to test_render_perf.html and manually control the profiler;r=nchevobbe
authorBrian Grinstead <bgrinstead@mozilla.com>
Wed, 07 Jun 2017 09:02:39 -0700
changeset 410953 14d24ce5d4aafa57ca7568b4a70a2c47c6569dc7
parent 410952 2135a8d8bed282a2982703828c503b334653ab2b
child 410954 50a90931ab2e1f58a48a8eb7f064a5dda9f73116
push id7391
push usermtabara@mozilla.com
push dateMon, 12 Jun 2017 13:08:53 +0000
treeherdermozilla-beta@2191d7f87e2e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersnchevobbe
bugs1370659
milestone55.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 1370659 - Add more measurements to test_render_perf.html and manually control the profiler;r=nchevobbe MozReview-Commit-ID: EO1vlWTSFZt
devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.html
--- a/devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.html
+++ b/devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.html
@@ -9,18 +9,32 @@
      - http://creativecommons.org/publicdomain/zero/1.0/ -->
 </head>
 <body>
 <p>Test for render perf</p>
 <div id="output"></div>
 
 <script type="text/javascript">
 "use strict";
-const numMessages = 4000;
-const testPackets = Array.from({length: numMessages}).map((el, id) => ({
+
+// To analyze the profile results:
+// > ./mach mochitest test_render_perf.html
+// Then open https://perf-html.io and drag the json file printed at the end of this test
+
+const NUM_MESSAGES = 4000;
+const NUM_STREAMING = 100;
+Components.utils.import("resource://gre/modules/FileUtils.jsm");
+const Services = browserRequire("Services");
+Services.prefs.setIntPref("devtools.hud.loglimit", NUM_MESSAGES);
+const NewConsoleOutputWrapper = browserRequire(
+  "devtools/client/webconsole/new-console-output/new-console-output-wrapper");
+const actions =
+  browserRequire("devtools/client/webconsole/new-console-output/actions/index");
+const EventEmitter = browserRequire("devtools/shared/event-emitter");
+const testPackets = Array.from({length: NUM_MESSAGES}).map((el, id) => ({
   "from": "server1.conn4.child1/consoleActor2",
   "type": "consoleAPICall",
   "message": {
     "arguments": [
       "foobar",
       `${id % 2 === 0 ? "Even" : "Odd"} text`,
       id
     ],
@@ -34,76 +48,144 @@ const testPackets = Array.from({length: 
     "private": false,
     "styles": [],
     "timeStamp": 1455064271115 + id,
     "timer": null,
     "workerType": "none",
     "category": "webdev"
   }
 }));
+const lastPacket = testPackets.pop();
 
 async function timeit(cb) {
   // Return a Promise that resolves the number of seconds cb takes.
   let start = performance.now();
   await cb();
   let elapsed = performance.now() - start;
   return elapsed;
 }
 
+async function addAllMessages(wrapper) {
+  let time = await timeit(async () => {
+    testPackets.forEach((packet) => wrapper.dispatchMessageAdd(packet));
+    // Only wait for the last packet to minimize work.
+    await wrapper.dispatchMessageAdd(lastPacket, true);
+    await new Promise(resolve => requestAnimationFrame(resolve));
+  });
+  return time;
+}
+
+async function addMessage(wrapper, message) {
+  return timeit(async () => {
+    await wrapper.dispatchMessageAdd(message, true);
+  });
+}
+
+function getTimes(times) {
+  times = times.sort();
+  let totalTime = times.reduce((sum, t) => sum + t);
+  let avg = totalTime / times.length;
+  let median = times.length % 2 !== 0
+    ? times[Math.floor(times.length / 2)]
+    : (times[(times.length / 2) - 1] + times[times.length / 2]) / 2;
+  return {avg, median};
+}
+
+async function clearMessages(wrapper) {
+  wrapper.dispatchMessagesClear();
+  await new Promise(resolve => requestAnimationFrame(resolve));
+}
+
+async function testStreamLogging(wrapper) {
+  await clearMessages(wrapper);
+  let streamTimes = [];
+  for (let i = 0; i < NUM_STREAMING; i++) {
+    streamTimes.push(addMessage(wrapper, testPackets[i]));
+    await new Promise(resolve => setTimeout(resolve, 100));
+  }
+  let {avg, median} = getTimes(await Promise.all(streamTimes));
+  info(`STREAMING: On average, it took ${avg} ms (median ${median} ms) ` +
+       `for each message`);
+}
+
+async function testBulkLogging(wrapper) {
+  await clearMessages(wrapper);
+  let bulkTimes = [];
+  const iterations = 5;
+  for (let i = 0; i < iterations; i++) {
+    let time = await addAllMessages(wrapper);
+    info(`took ${time} ms to render bulk messages (iteration ${i})`);
+    bulkTimes.push(time);
+
+    await clearMessages(wrapper);
+  }
+  let {avg, median} = getTimes(bulkTimes);
+
+  info(`BULK: On average, it took ${avg} ms (median ${median} ms) ` +
+       `to render ${NUM_MESSAGES} messages`);
+}
+
+async function testFiltering(wrapper) {
+  await clearMessages(wrapper);
+  await addAllMessages(wrapper);
+  let filterToggleTimeOff = await timeit(() => {
+    wrapper.getStore().dispatch(actions.filterToggle("log"));
+  });
+  info(`Filter toggle time (off): ${filterToggleTimeOff}`);
+
+  let filterToggleTimeOn = await timeit(() => {
+    wrapper.getStore().dispatch(actions.filterToggle("log"));
+  });
+  info(`Filter toggle time (on): ${filterToggleTimeOn}`);
+}
+
 window.onload = async function () {
   // This test does costly work multiple times to have better performance data.
+  // It doesn't run in automation
   SimpleTest.requestLongerTimeout(3);
 
-  try {
-    const Services = browserRequire("Services");
-    Services.prefs.setIntPref("devtools.hud.loglimit", numMessages);
-    const NewConsoleOutputWrapper = browserRequire(
-      "devtools/client/webconsole/new-console-output/new-console-output-wrapper");
-    const EventEmitter = browserRequire("devtools/shared/event-emitter");
-
-    const wrapper = new NewConsoleOutputWrapper(
-      document.getElementById("output"),
-      {hud: EventEmitter.decorate({proxy: {}})},
-      {},
-      null,
-      document,
-    );
-    wrapper.init();
+  const wrapper = new NewConsoleOutputWrapper(
+    document.getElementById("output"),
+    {hud: EventEmitter.decorate({proxy: {}})},
+    {},
+    null,
+    document,
+  );
+  wrapper.init();
 
-    let times = [];
-    const iterations = 25;
-    const lastPacket = testPackets.pop();
-    for (let i = 0; i < iterations; i++) {
-      let time = await timeit(async () => {
-        testPackets.forEach((packet) => wrapper.dispatchMessageAdd(packet));
-        // Only wait for the last packet to minimize work.
-        await wrapper.dispatchMessageAdd(lastPacket, true);
-        await new Promise(resolve => requestAnimationFrame(resolve));
-      });
-      info(`took ${time} ms to render messages`);
-      times.push(time);
+  // From https://github.com/devtools-html/perf.html/blob/b73eb73df04c7df51464fa50eeadef3dc7f5d4e2/docs/gecko-profile-format.md#L21
+  const settings = {
+    entries: 100000000,
+    interval: 1,
+    features: ["js"],
+    threads: ["GeckoMain"]
+  };
+  Services.profiler.StartProfiler(
+    settings.entries,
+    settings.interval,
+    settings.features,
+    settings.features.length,
+    settings.threads,
+    settings.threads.length
+  );
+  info("Profiler has started");
 
-      // Clear the console
-      wrapper.dispatchMessagesClear();
-      await new Promise(resolve => requestAnimationFrame(resolve));
-    }
+  Services.profiler.AddMarker("Stream Logging");
+  await testStreamLogging(wrapper);
+
+  Services.profiler.AddMarker("Bulk Logging");
+  await testBulkLogging(wrapper);
 
-    times.sort();
-    let totalTime = times.reduce((sum, t) => sum + t);
-    let avg = totalTime / times.length;
-    let median = times.length % 2 !== 0
-      ? times[Math.floor(times.length / 2)]
-      : (times[(times.length / 2) - 1] + times[times.length / 2]) / 2;
-    info(`On average, it took ${avg} ms (median ${median} ms) ` +
-         `to render ${numMessages} messages`);
+  Services.profiler.AddMarker("Filtering Logging");
+  await testFiltering(wrapper);
+
+  ok(true, "Tests finished");
 
-    ok(true, "Yay, it didn't time out!");
-  } catch (e) {
-    ok(false, `Error :  ${e.message}
-      ${e.stack}
-    `);
-  }
+  let file = FileUtils.getFile("TmpD", [`test_render_perf_${Date.now()}.json`]);
+  info("PROFILE:\n\n\n\n\nSaving profile " + file.path + "\n\n\n\n\n");
+  Services.profiler.dumpProfileToFile(file.path);
+  Services.profiler.StopProfiler();
 
   SimpleTest.finish();
 };
 </script>
 </body>
 </html>