1419328 - Run DAMP open/reload/close tests against a document specific to console

Status: RESOLVED FIXED

(DevTools :: Console, enhancement, P2)

Description

[Alexandre Poirot [:ochameau]]

Following bug 1415532, we should also run DAMP test against a custom document, made up for the console.

Comment 1

[Alexandre Poirot [:ochameau]]

Attachment: Bug 1419328 - Run DAMP test against a document specific to the webconsole.

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

Comment 2

[Alexandre Poirot [:ochameau]]

Comment on attachment 8930928 [details]
Bug 1419328 - Run DAMP test against a document specific to the webconsole.

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

Comment 3

[Alexandre Poirot [:ochameau]]

Comment on attachment 8930928 [details]
Bug 1419328 - Run DAMP test against a document specific to the webconsole.

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

Comment 4

[Alexandre Poirot [:ochameau]]

Nicolas, this test tries to stress out the console by doing a lot of logs in ways that forces it to do many updates.
requestIdleCallback ensure that there is no bulk update and so forces the console to do individual updates.
Here is the test results, custom.webconsole runs longer than complicated.

Any ideas on how to stress the console even more?

Comment 5

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8930928 [details]
Bug 1419328 - Run DAMP test against a document specific to the webconsole.

https://reviewboard.mozilla.org/r/202032/#review221204

This looks good to me.
You could also have a test for what we call "streaming", i.e. logging lots of things in a short timespan, in an async manner, like : 


```js
let i = 0;
function streamLogs() {
  console.log(i++);
  if (i < 500) {
    requestAnimationFrame(streamLogs)
  }
}
streamLogs();
```

Comment 6

[Alexandre Poirot [:ochameau]]

Comment on attachment 8930928 [details]
Bug 1419328 - Run DAMP test against a document specific to the webconsole.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/202032/diff/3-4/

Comment 7

[Alexandre Poirot [:ochameau]]

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #5)
> Comment on attachment 8930928 [details]
> Bug 1419328 - Run DAMP test against a document specific to the webconsole.
> 
> https://reviewboard.mozilla.org/r/202032/#review221204
> 
> This looks good to me.
> You could also have a test for what we call "streaming", i.e. logging lots
> of things in a short timespan, in an async manner, like : 

I added a streaming test, but looped only over 250 console log calls:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=mozilla-central&newProject=try&newRevision=1822846d86eceedaa3591e7b5fb5bc7610a09e40&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&filter=custom.web&framework=1&selectedTimeRange=172800

I tried with 500 (for all tests: sync, async and stream), but it slow down the whole test suite:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=mozilla-central&newProject=try&newRevision=f93ff56f4ea93577fa7946a226d7933fa9886a31&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyConfident=1&framework=1&selectedTimeRange=172800
And makes the reload test last for 17s, instead of 9s with only 250 calls.

Comment 8

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8930928 [details]
Bug 1419328 - Run DAMP test against a document specific to the webconsole.

https://reviewboard.mozilla.org/r/202032/#review221602

One nit, and let's see if we can pass the numbers from damp.js to console.html via GET params instead of syncing numbers

::: testing/talos/talos/tests/devtools/addon/content/pages/custom/console.html:16
(Diff revisions 3 - 4)
> +let bigArray = new Array(10000);
> +for (let i = 0; i < bigArray.length; i++) {
> +  bigArray[i] = i;
> +}

we can do this with 
```js
let bigArray = Array.from({length: 10000}, (_, i) => i);
```

Comment 9

[Alexandre Poirot [:ochameau]]

Comment on attachment 8930928 [details]
Bug 1419328 - Run DAMP test against a document specific to the webconsole.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/202032/diff/4-5/

Comment 10

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8930928 [details]
Bug 1419328 - Run DAMP test against a document specific to the webconsole.

https://reviewboard.mozilla.org/r/202032/#review221604

::: testing/talos/talos/tests/devtools/addon/content/pages/custom/console.html:11
(Diff revision 5)
> +</head>
> +<body>
> +<script>
> +// These query parameters are set in damp.js:customConsole and define the number
> +// of console API calls we do in this test.
> +let {searchParams} = new URL(window.location);

nit: Maybe 
```js
const searchParams = new URLSearchParams(location.search);
```

would be better suited

Comment 11

[Alexandre Poirot [:ochameau]]

Before landing this test, I tried to better understand the impact of each type of message.
So I tweaked sync, stream and async counts individually to 500 and compared with a base run with 250 logs of all types.

sync = 500
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=5198e7cade1ea7d2a5e1cb7116cf4cc2a5bd43bb&newProject=try&newRevision=7765a343bb2c5bb57147fce9203896201634b392&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyConfident=1&framework=1
This really stress out the console and makes most DAMP test running after the console much slower to run!
  custom.webconsole.open +34%
  custom.webconsole.reload +28%
Note that it impacts both opening and page reload.

stream = 500
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=5198e7cade1ea7d2a5e1cb7116cf4cc2a5bd43bb&newProject=try&newRevision=3cfb3620a1c1155857cffd28447a5c28f76df060&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyConfident=1&framework=1
  custom.webconsole.reload +28%
This time, it only impacts page reload. But it also slow down many tests running after the console test!

async = 500
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=5198e7cade1ea7d2a5e1cb7116cf4cc2a5bd43bb&newProject=try&newRevision=9241d6f8259927ccca1c1fee37682a43501797c9&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyConfident=1&framework=1
  custom.webconsole.reload +35%
  custom.webconsole.reload.settle +167%
  custom.webconsole.close +260%
Finally, async doesn't impact following tests at all. It only impacts page reload. But it highlights that we may not wait properly for async code running in the console as reload.settle and close are increased *a lot*.

Comment 12

[Alexandre Poirot [:ochameau]]

(In reply to Alexandre Poirot [:ochameau] from comment #11)
> async = 500
> https://treeherder.mozilla.org/perf.html#/
> comparesubtest?originalProject=try&originalRevision=5198e7cade1ea7d2a5e1cb711
> 6cf4cc2a5bd43bb&newProject=try&newRevision=9241d6f8259927ccca1c1fee37682a4350
> 1797c9&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignatur
> e=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyConfident=1&framework=1
>   custom.webconsole.reload +35%
>   custom.webconsole.reload.settle +167%
>   custom.webconsole.close +260%
> Finally, async doesn't impact following tests at all. It only impacts page
> reload. But it highlights that we may not wait properly for async code
> running in the console as reload.settle and close are increased *a lot*.

About that, I can't see any JS code still running during settle and reload.
There is reflows going on during "reload.settle" and "close" is mostly
made of this innerHTML call from jsterm:
  https://searchfox.org/mozilla-central/source/devtools/client/webconsole/jsterm.js#
and a lot of GC. I imagine close is just slower as we increase the number of log messages we log.

I looked into BHR data and can't find any stack related to jsterm.js's destroy.

Comment 13

[Alexandre Poirot [:ochameau]]

(In reply to Alexandre Poirot [:ochameau] from comment #12)
> About that, I can't see any JS code still running during settle and reload.
> There is reflows going on during "reload.settle" and "close" is mostly
> made of this innerHTML call from jsterm:

I opened bug 1434207 about that.

Comment 14

[Alexandre Poirot [:ochameau]]

Comment on attachment 8930928 [details]
Bug 1419328 - Run DAMP test against a document specific to the webconsole.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/202032/diff/5-6/

Comment 15

[Alexandre Poirot [:ochameau]]

I've been confused by DAMP results because of the new hardware, but when comparing against a custom base run,
we can see that the new test don't have too much impact on the other tests. Mostly close/settle subtests:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=ab56d15818914c66742bbdc08daed81ea0e8a072&newProject=try&newRevision=3616220b3447146c89fc32f79cb3cd22f6a14418&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyConfident=1&framework=1

Comment 16

[Alexandre Poirot [:ochameau]]

Comment on attachment 8930928 [details]
Bug 1419328 - Run DAMP test against a document specific to the webconsole.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/202032/diff/6-7/

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/2927a89dd437
Run DAMP test against a document specific to the webconsole. r=nchevobbe

Comment 18

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/2927a89dd437