Update test_render_perf.html to be more authoritative

RESOLVED FIXED in Firefox 55

Status

enhancement
P1
normal
RESOLVED FIXED
2 years ago
Last year

People

(Reporter: bgrins, Assigned: bgrins)

Tracking

unspecified
Firefox 55
Dependency tree / graph
Bug Flags:
qe-verify -

Firefox Tracking Flags

(firefox55 fixed)

Details

(Whiteboard: [console-html])

Attachments

(1 attachment)

Assignee

Description

2 years ago
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
Flags: qe-verify?
Whiteboard: [console-html] → [console-html] [triage]
Assignee: nobody → bgrinstead
Status: NEW → ASSIGNED
Iteration: --- → 55.7 - Jun 12
Priority: -- → P1
Whiteboard: [console-html] [triage] → [console-html]

Comment 2

2 years ago
mozreview-review
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 :)
Attachment #8875048 - Flags: review?(nchevobbe) → review+
Assignee

Comment 3

2 years ago
(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 hidden (mozreview-request)

Comment 5

2 years ago
Pushed by bgrinstead@mozilla.com:
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

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/14d24ce5d4aa
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 55
Assignee

Updated

2 years ago
Depends on: 1371452
Flags: qe-verify? → qe-verify-

Updated

Last year
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.