Bug 1372814 - Add test case and performance measurement in test-perf.html . r=bgrins draft
authorNicolas Chevobbe <nchevobbe@mozilla.com>
Wed, 14 Jun 2017 17:13:52 +0200
changeset 596777 c8dca67060c2bf6a61e32c78e9fb35b24d7801a9
parent 596219 95543bdc59bd038a3d5d084b85a4fec493c349ee
child 634067 01f6d8b4c0e483d864e444e7c3b872c63900fd0f
push id64753
push userbmo:nchevobbe@mozilla.com
push dateMon, 19 Jun 2017 19:21:59 +0000
reviewersbgrins
bugs1372814
milestone56.0a1
Bug 1372814 - Add test case and performance measurement in test-perf.html . r=bgrins Add a test case to measure streaming time when the store already hit the log limit so we can have data about pruning. Switch to performance.mark and performance.measure for time measurement instead of the custom timeit function we had. This allow us to have precise data, and also those are written in the profile and then shown in perf-html, so we can have a better overview of what's going on during the test. MozReview-Commit-ID: 2nNmukxmUso
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
@@ -50,38 +50,44 @@ const testPackets = Array.from({length: 
     "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;
+function startMeasure(label) {
+  const startLabel = label + "start";
+  performance.mark(startLabel);
+  return {
+    stop: (clear = true) => {
+      performance.measure(label, startLabel);
+      const entries = performance.getEntriesByName(label);
+      if (clear) {
+        performance.clearMeasures(label);
+      }
+      return entries[entries.length - 1];
+    }
+  };
+}
+
+function wait(time) {
+  return new Promise(resolve => setTimeout(resolve, time));
 }
 
 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;
+  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));
 }
 
 async function addMessage(wrapper, message) {
-  return timeit(async () => {
-    await wrapper.dispatchMessageAdd(message, true);
-  });
+  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)]
@@ -89,57 +95,79 @@ function getTimes(times) {
   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);
+    const measure = startMeasure("bulk log");
+    await addAllMessages(wrapper);
+    const {duration} = measure.stop();
+
+    info(`took ${duration} ms to render bulk messages (iteration ${i})`);
+    bulkTimes.push(duration);
 
-    await clearMessages(wrapper);
+    // Do not clear the store on last iteration so the next test can use the messages.
+    if (i !== iterations - 1) {
+      // Wait before clearing messages so those events are more spotable on the profile.
+      await wait(500);
+      await clearMessages(wrapper);
+      await wait(500);
+    }
   }
   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}`);
+  const measureFilter = startMeasure("filtering");
+
+  const measureFilterOff = startMeasure("filtering off");
+  await wrapper.getStore().dispatch(actions.filterToggle("log"));
+  const measureFilterOffEntry = measureFilterOff.stop();
+  info(`Filter toggle time (off): ${measureFilterOffEntry.duration}`);
+
+  const measureFilterOn = startMeasure("filtering on");
+  await wrapper.getStore().dispatch(actions.filterToggle("log"));
+  const measureFilterOnEntry = measureFilterOn.stop();
+  info(`Filter toggle time (on): ${measureFilterOnEntry.duration}`);
+  measureFilter.stop();
+}
 
-  let filterToggleTimeOn = await timeit(() => {
-    wrapper.getStore().dispatch(actions.filterToggle("log"));
-  });
-  info(`Filter toggle time (on): ${filterToggleTimeOn}`);
+async function testStreamLogging(wrapper, clear = true) {
+  const streamMeasureLabel = "stream" + (clear === false ? " and prune" : "");
+  const streamMeasure = startMeasure(streamMeasureLabel);
+  if (clear === true) {
+    await clearMessages(wrapper);
+  }
+
+  const measureLabel = "stream - add single message";
+  for (let i = 0; i < NUM_STREAMING; i++) {
+    const measure = startMeasure(measureLabel);
+    await addMessage(wrapper, testPackets[i]);
+    measure.stop(false);
+    await new Promise(resolve => setTimeout(resolve, 100));
+  }
+
+  let streamTimes = performance.getEntriesByName(measureLabel)
+    .map(entry => entry.duration);
+  performance.clearMeasures(measureLabel);
+  let { avg, median } = getTimes(streamTimes);
+  info(`STREAMING${clear === false ? " AND PRUNING" : ""}: On average, ` +
+    `it took ${avg} ms (median ${median} ms) for each message`);
+  streamMeasure.stop();
 }
 
 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);
 
   const wrapper = new NewConsoleOutputWrapper(
@@ -163,25 +191,33 @@ window.onload = async function () {
     settings.interval,
     settings.features,
     settings.features.length,
     settings.threads,
     settings.threads.length
   );
   info("Profiler has started");
 
-  Services.profiler.AddMarker("Stream Logging");
-  await testStreamLogging(wrapper);
+  await wait(500);
 
-  Services.profiler.AddMarker("Bulk Logging");
   await testBulkLogging(wrapper);
 
-  Services.profiler.AddMarker("Filtering Logging");
+  await wait(500);
+
   await testFiltering(wrapper);
 
+  await wait(500);
+
+  // first pass, without clearing the store.
+  await testStreamLogging(wrapper, false);
+
+  await wait(500);
+  // second pass, with an empty store.
+  await testStreamLogging(wrapper, true);
+
   ok(true, "Tests finished");
 
   let file = FileUtils.getFile("TmpD", [`test_render_perf_${Date.now()}.json`]);
   Services.profiler.dumpProfileToFile(file.path);
   Services.profiler.StopProfiler();
 
   info(`