devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.html
author Brian Grinstead <bgrinstead@mozilla.com>
Wed, 07 Jun 2017 09:02:39 -0700
changeset 362836 14d24ce5d4aafa57ca7568b4a70a2c47c6569dc7
parent 355033 0251b80953518481f3edd5493c01e5a7eb1a49f1
child 363437 daa0394d99737310d2595b63db235ba0d4498ca9
permissions -rw-r--r--
Bug 1370659 - Add more measurements to test_render_perf.html and manually control the profiler;r=nchevobbe MozReview-Commit-ID: EO1vlWTSFZt

<!DOCTYPE HTML>
<html lang="en">
<head>
  <meta charset="utf8">
  <title>Test for getRepeatId()</title>
  <script type="text/javascript" src="chrome://mochikit/content/tests/SimpleTest/SimpleTest.js"></script>
  <script type="application/javascript" src="head.js"></script>
  <!-- Any copyright is dedicated to the Public Domain.
     - 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";

// 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
    ],
    "columnNumber": 1,
    "counter": null,
    "filename": "file:///test.html",
    "functionName": "",
    "groupName": "",
    "level": "log",
    "lineNumber": 1,
    "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);

  const wrapper = new NewConsoleOutputWrapper(
    document.getElementById("output"),
    {hud: EventEmitter.decorate({proxy: {}})},
    {},
    null,
    document,
  );
  wrapper.init();

  // 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");

  Services.profiler.AddMarker("Stream Logging");
  await testStreamLogging(wrapper);

  Services.profiler.AddMarker("Bulk Logging");
  await testBulkLogging(wrapper);

  Services.profiler.AddMarker("Filtering Logging");
  await testFiltering(wrapper);

  ok(true, "Tests finished");

  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>