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
--- 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(`