1370659 - Update test_render_perf.html to be more authoritative

Status: RESOLVED FIXED

(DevTools :: Console, enhancement, P1)

Description

[Brian Grinstead [:bgrins]]

Right now test_render_perf.html covers only bulk logging, and also it gives erratic results.

I plan to add stream logging, filter perf, and hopefully sort out some of the reliability issues in this bug

Comment 1

[Brian Grinstead [:bgrins]]

Attachment: Bug 1370659 - Add more measurements to test_render_perf.html and manually control the profiler;

Review commit: https://reviewboard.mozilla.org/r/146410/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/146410/

Comment 2

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8875048 [details]
Bug 1370659 - Add more measurements to test_render_perf.html and manually control the profiler;

https://reviewboard.mozilla.org/r/146410/#review150532

This is looking good.
I have only a few comments, but it's already good to land as is I think.

::: devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.html:18
(Diff revision 1)
> -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 on the json file printed at the end of this test

Nice idea :)
I wonder if we could automate that (load the profile on perf-html, upload it and print the url to the uploaded profile)

::: devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.html:92
(Diff revision 1)
> +    : (times[(times.length / 2) - 1] + times[times.length / 2]) / 2;
> +  return {avg, median};
> +}
> +
> +async function testStreamLogging(wrapper) {
> +  let streamTimes = [];

Maybe we should call `dispatchMessagesClear` here so the test is always run with the same store, no matter what was run before.

::: devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.html:95
(Diff revision 1)
> +
> +async function testStreamLogging(wrapper) {
> +  let streamTimes = [];
> +  for (let i = 0; i < NUM_STREAMING; i++) {
> +    streamTimes.push(addMessage(wrapper, testPackets[i]));
> +    await new Promise(resolve => setTimeout(resolve, 100));

100ms seems a bit long for me. It gaves the console enough time not to be stressed.
I'm thinking of case where a log is in a raf loop, or when a mousemove/scroll event is logged , which might be when the console suffers the most.

What do you think of this ?

::: devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.html:123
(Diff revision 1)
> +  info(`BULK: On average, it took ${avg} ms (median ${median} ms) ` +
> +       `to render ${NUM_MESSAGES} messages`);
> +}
> +
> +async function testFiltering(wrapper) {
> +  await addAllMessages(wrapper);

Maybe we should call `dispatchMessagesClear` here so the test is always run with the same store, no matter what was run before.

::: devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.html:124
(Diff revision 1)
> +  let filterToggleTimeOff = await timeit(() => {
> +    wrapper.getStore().dispatch(actions.filterToggle("log"));
> +  });

are we sure here that this measure the time to render ?
I'm thinking that if we enable the debounce middleware it might not be the case anymore.

We might handle this in the patch that enable the middleware, but we need to make sure to not forget to do it.

::: devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.html:177
(Diff revision 1)
> -    ok(true, "Yay, it didn't time out!");
> -  } catch (e) {
> -    ok(false, `Error :  ${e.message}
> -      ${e.stack}
> -    `);
> -  }
> +  Services.profiler.AddMarker("Filtering Logging");
> +  await testFiltering(wrapper);
> +
> +  ok(true, "Tests finished");
> +
> +  let file = FileUtils.getFile("TmpD", [`test_render_perf_${(new Date()).getTime()}.json`]);

nit: We could use `Date.now()` that has the same output than `(new Date()).getTime()` and is a bit shorter :)

Comment 3

[Brian Grinstead [:bgrins]]

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #2)
> Comment on attachment 8875048 [details]
> Bug 1370659 - Add more measurements to test_render_perf.html and manually
> control the profiler;
> 
> https://reviewboard.mozilla.org/r/146410/#review150532
> 
> This is looking good.
> I have only a few comments, but it's already good to land as is I think.
> 
> :::
> devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.
> html:18
> (Diff revision 1)
> > -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 on the json file printed at the end of this test
> 
> Nice idea :)
> I wonder if we could automate that (load the profile on perf-html, upload it
> and print the url to the uploaded profile)

Unfortunately I don't think there is a way to do that yet yet. Agree it would be much better if we could add a way to post this from the command line

> :::
> devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.
> html:92
> (Diff revision 1)
> > +    : (times[(times.length / 2) - 1] + times[times.length / 2]) / 2;
> > +  return {avg, median};
> > +}
> > +
> > +async function testStreamLogging(wrapper) {
> > +  let streamTimes = [];
> 
> Maybe we should call `dispatchMessagesClear` here so the test is always run
> with the same store, no matter what was run before.
> 
> :::
> devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.
> html:95
> (Diff revision 1)
> > +
> > +async function testStreamLogging(wrapper) {
> > +  let streamTimes = [];
> > +  for (let i = 0; i < NUM_STREAMING; i++) {
> > +    streamTimes.push(addMessage(wrapper, testPackets[i]));
> > +    await new Promise(resolve => setTimeout(resolve, 100));
> 
> 100ms seems a bit long for me. It gaves the console enough time not to be
> stressed.
> I'm thinking of case where a log is in a raf loop, or when a
> mousemove/scroll event is logged , which might be when the console suffers
> the most.
> 
> What do you think of this ?
> 
> :::
> devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.
> html:123
> (Diff revision 1)
> > +  info(`BULK: On average, it took ${avg} ms (median ${median} ms) ` +
> > +       `to render ${NUM_MESSAGES} messages`);
> > +}
> > +
> > +async function testFiltering(wrapper) {
> > +  await addAllMessages(wrapper);
> 
> Maybe we should call `dispatchMessagesClear` here so the test is always run
> with the same store, no matter what was run before.

Good idea

> :::
> devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.
> html:124
> (Diff revision 1)
> > +  let filterToggleTimeOff = await timeit(() => {
> > +    wrapper.getStore().dispatch(actions.filterToggle("log"));
> > +  });
> 
> are we sure here that this measure the time to render ?
> I'm thinking that if we enable the debounce middleware it might not be the
> case anymore.
> 
> We might handle this in the patch that enable the middleware, but we need to
> make sure to not forget to do it.

I'm pretty sure the debounce middleware is opt-in and we are only using it when adding messages or updating network messages.

> :::
> devtools/client/webconsole/new-console-output/test/chrome/test_render_perf.
> html:177
> (Diff revision 1)
> > -    ok(true, "Yay, it didn't time out!");
> > -  } catch (e) {
> > -    ok(false, `Error :  ${e.message}
> > -      ${e.stack}
> > -    `);
> > -  }
> > +  Services.profiler.AddMarker("Filtering Logging");
> > +  await testFiltering(wrapper);
> > +
> > +  ok(true, "Tests finished");
> > +
> > +  let file = FileUtils.getFile("TmpD", [`test_render_perf_${(new Date()).getTime()}.json`]);
> 
> nit: We could use `Date.now()` that has the same output than `(new
> Date()).getTime()` and is a bit shorter :)

Done

Comment 4

[Brian Grinstead [:bgrins]]

Comment on attachment 8875048 [details]
Bug 1370659 - Add more measurements to test_render_perf.html and manually control the profiler;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/146410/diff/1-2/

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/14d24ce5d4aa
Add more measurements to test_render_perf.html and manually control the profiler;r=nchevobbe

Comment 6

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/14d24ce5d4aa