1423517 - Help tracking JS allocations when running DevTools tests

Status: RESOLVED FIXED

(DevTools :: General, enhancement, P4)

Description

[Alexandre Poirot [:ochameau]]

I've been using an helper script for quite a while locally.
Other DevTools requested interest in seeing data about JS objects allocations while running the tools.

I'll publish a version of this script here to discuss about this.
Note that so far it was often misleading and it is always hard to interpret.
Mostly because you end up in 80% of the cases into helper libraries, like react, module loader, codemirror, immutable, ... and it is hard to figure out what of our own code introduces such allocations.

Also, I've been using this helper script a lot while working on bug 1392602.
The script reports tons of objects being allocated by the Loader.
I wrote many patches to try to reduce these numbers. I sometimes achieved to reduce drastically the allocations, but it never ended up reporting any significant win on DAMP. So there isn't always a direct relation between the allocations and performances.

My experience while using it against bug 1399242 was really different.
It helps me uncover ImmutableJS overhead in debugger. It helped me do attachment 8909337 [details] [diff] [review]. Where the "url" helper module was called many times and instanciates many JS objects. And this piece of code, using Immutable was also allocation tons of objects and it is being called many times: https://github.com/devtools-html/debugger.html/blob/7985f7e5e17de7ae026b609b7e740696663c8a2b/src/components/PrimaryPanes/SourcesTree.js#L176-L180

Overall, my suggestion is to use the profiler. It is still the most effective way to understand and find performance issues, by far.

Comment 1

[Alexandre Poirot [:ochameau]]

Attachment: Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

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

Comment 2

[Alexandre Poirot [:ochameau]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

Please have a look, tell me if that worth landing or if we should keep that in a patch you manually apply to give it a try for now.
You can test this via:
  DEBUG_ALLOCATIONS=1 ./mach talos-test --activeTests damp --cycles 1 --tppagecycles 1 --subtest simple.inspector
and
  DEBUG_ALLOCATIONS=1 ./mach mochitest devtools/client/framework/test/browser_toolbox_ready.js

I may submit some other test helpers like that. Only shipped in local builds that can be manually used in test. I'm thinking about the canvas screenshot helper, which we have to copy from a gist everytime we need it...

Otherwise, about this patch. One challenge is the output. It is hard to do much better without spending a lot of time building a UI for it.
The only cheap opportunity I'm thinking about would be to generate a code coverage file as output. If codecoverage files supports a "value" and that a tool accepts displaying such value (which would be the number of allocations), that could be helpful and easy to do.

Comment 3

[Alexandre Poirot [:ochameau]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

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

Comment 4

[Alexandre Poirot [:ochameau]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

Sorry, I forgot to add some files...

Comment 5

[Alexandre Poirot [:ochameau]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

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

Comment 6

[Alexandre Poirot [:ochameau]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

When it doesn't want... it does not!

Comment 7

[Julian Descottes [:jdescottes]]

Sorry about the delay here. The main reason I was interested in this script was to check if it would be a viable addition to our DAMP tests. If the allocations count is stable then we could try to track it with TALOS.

I quickly modified DAMP to also log the allocations count. For the inspector, I get a 15% variance on the allocations count (5% if we exclude the first measure, which I think is what perfherder takes into account?). 5% is still high but I haven't rebased on top of your latest patches that wait for reflows/RDP, maybe that would bring down the variance down.

Overall I would say that if we don't have a real consumer for this code it's probably best to keep it out of the tree (afraid it would end up being unmaintained after a while). As you say it's pretty advanced, can be misleading, doesn't yet have an easy to read output.

But if we can integrate it in DAMP and use it to spot regressions that directly impact the allocations count, then it's worth landing.

Comment 8

[Julian Descottes [:jdescottes]]

Attachment: log allocation count in DAMP

Just to illustrate. One thing about that is that we would need to run it as a separate test suite, I suppose recording allocations impacts the overall performance.

Comment 9

[Julian Descottes [:jdescottes]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

Overall I think it is really a nice helper to have. I'm just worried about it going unmaintained if we don't have a real usage for it.

If it is not worth tracking in DAMP and should just be an investigation tool, we can still land it in tree. We are just starting our performance efforts in DevTools, maybe it is a good time to have this tool in tree, usable by anybody easily. We can review mid 2018 if it was useful to investigate performance issues or not, and then decide to keep it in tree or not.

Comment 10

[Alexandre Poirot [:ochameau]]

I tried pushing this to try to see how stable the results are, and they are very stable for most tests:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=mozilla-central&newProject=try&newRevision=1eaf743bc584663f5154589d54c7065dbadd576c&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&filter=alloca&framework=1&selectedTimeRange=172800
Now, as you said, it isn't that easy to run because:
* it slow down tests *a lot*, up to 180%!!
* it makes DAMP time out.
* my trick where I ship this helper folder only for local builds (MOZ_OFFICIAL!=1) doesn't work for Talos as it runs against official builds.

So if we want to consider this, it should run in its own job, the tests shond run only once and ignore all results but allocations.

The main issue is that it complexify the whole story. It means that both on automation and locally for developers, we may need to run DAMP in both modes.

But that may be useful to push this to try every now to see what is the overall trend. See if we have increased memory usage over time without timing regression. I imagine both time to run test and object creations are related and should evolve similarely.

My idea with this patch was to help identifying slow functions, allocating tons of objects, rather than tracking a new metric on DAMP. Regarding landing it as an investigation tool, I'm wondering if I should land it without having anyone trying it against a real perf issue? Having said that, this did not worked out well for bug 1310653.

Comment 11

[Julian Descottes [:jdescottes]]

Yes, we can't both not ship the script and use it on Talos. The script being pretty small I imagined it could be acceptable. But other than that I totally agree, it needs to run in a separate job. I didn't necessarily expect DAMP to timeout, though. Let's forget about adding it to DAMP for the moment. 

I still believe it would be nice to have in tree, because once the code lands, it's easy to enable. My hope is that we encourage other devtools developers to use the script during the coming months, as we investigate performance issues. If the code is available it makes it easy for others to try. Then if nobody used it after some time, we should remove it from the tree.

Comment 12

[Alexandre Poirot [:ochameau]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

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

Comment 13

[Alexandre Poirot [:ochameau]]

I tweaked the patch slightly to support both modes:
DEBUG_ALLOCATIONS=1 will print the detail of all allocation sites at the end of DAMP/mochitest
COUNT_ALLOCATIONS=1 will record allocations for each subtest, in a new subtest with ".allocations" prefix. In mochitest it just prints the number of allocations at the end of test.

Comment 14

[Julian Descottes [:jdescottes]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

https://reviewboard.mozilla.org/r/205842/#review219242

Some comments. Based on the current patch, I'm not sure if we are trying to push some results to Talos (in CI, not just locally).
I like the two modes but I think I could see 3 modes:
- DEBUG_ALLOCATIONS = "normal" => just prints the count
- DEBUG_ALLOCATIONS = "verbose" => prints the more complex output
- COUNT_ALLOCATIONS = "1" => push allocations count during DAMP tests

I'm not sure we should actually do COUNT_ALLOCATIONS right now, if we don't push anything to CI. 
But for the logging part, shared-head and damp could just check that DEBUG_ALLOCATIONS is set to something and let the helper decide what to log depending on the value of the environment variable.
That would reduce a bit the consumed API of the helper in our real code.

Regarding the name of the variables, maybe we should mention DEVTOOLS in their names? eg. DEBUG_DEVTOOLS_ALLOCATIONS

::: devtools/shared/moz.build:36
(Diff revision 4)
>      'transport',
>      'webconsole',
>      'worker',
>  ]
>  
> +DIRS += ['test-helpers']

Should be for local builds only?

::: devtools/shared/test-helpers/moz.build:1
(Diff revision 4)
>  # -*- Mode: python; indent-tabs-mode: nil; tab-width: 40 -*-

This file was marked as copied by mercurial. Would be easier to read if it was treated as a new file.

::: devtools/shared/test-helpers/allocation-tracker.js:6
(Diff revision 4)
> +/* this source code form is subject to the terms of the mozilla public
> + * license, v. 2.0. if a copy of the mpl was not distributed with this
> + * file, you can obtain one at http://mozilla.org/mpl/2.0/. */
> +
> +"use strict";
> +

Would be nice to have a small JS doc here describing the file and how to use it.

eg.

"This file helps tracking allocations when running DevTools tests (either mochitests or DAMP). It is only included in local builds. To use it, you need to set the following environment variables:
{list the variables with possible values and description}

For instance you can use it as follows:
{example of starting a mochitest or a DAMP test with the variable set, to have easy one liners to copy paste}
"

::: testing/talos/talos/test.py:442
(Diff revision 4)
>      Tests the speed of DevTools toolbox open, close, and page reload
>      for each tool, across a very simple and very complicated page.
>      """
>      tpmanifest = '${talos}/tests/devtools/damp.manifest'
>      extensions = '${talos}/tests/devtools/addon'
> -    cycles = 5
> +    cycles = 1

We don't want to change the default I assume?

::: testing/talos/talos/test.py:444
(Diff revision 4)
>      """
>      tpmanifest = '${talos}/tests/devtools/damp.manifest'
>      extensions = '${talos}/tests/devtools/addon'
> -    cycles = 5
> +    cycles = 1
>      tpcycles = 1
> -    tppagecycles = 5
> +    tppagecycles = 1

ditto

::: testing/talos/talos/tests/devtools/addon/content/damp.js:260
(Diff revision 4)
> +        if (COUNT_ALLOCATIONS) {
> +          this._results.push({
> +            name: label + ".allocations",
> +            value: this.allocationTracker.countAllocations()
> +          });

Since it will not actually run on CI, I'm not convinced we should push the results here.

::: testing/talos/talos/tests/devtools/addon/content/damp.js:1126
(Diff revision 4)
>      // Free memory before running the first test, otherwise we may have a GC
>      // related to Firefox startup or DAMP setup during the first test.
>      garbageCollect().then(() => {
>        this._doSequence(sequenceArray, this._doneInternal);
> +    }, e => {
> +      dump("Exception while running DAMP tests: " + e + "\n" + e.stack + "\n");

I'm always confused by then()'s second argument, but I think this will only catch errors from garbageCollect() right? Use .catch() to better match the error description.

Comment 15

[Alexandre Poirot [:ochameau]]

(In reply to Julian Descottes [:jdescottes][:julian] from comment #14)
> Comment on attachment 8934917 [details]
> Bug 1423517 - Helps tracking JS allocations when running DevTools tests.
> 
> https://reviewboard.mozilla.org/r/205842/#review219242
> 
> Some comments. Based on the current patch, I'm not sure if we are trying to
> push some results to Talos (in CI, not just locally).
> I like the two modes but I think I could see 3 modes:
> - DEBUG_ALLOCATIONS = "normal" => just prints the count
> - DEBUG_ALLOCATIONS = "verbose" => prints the more complex output
> - COUNT_ALLOCATIONS = "1" => push allocations count during DAMP tests
> 
> I'm not sure we should actually do COUNT_ALLOCATIONS right now, if we don't
> push anything to CI.

I went for supporting only DEBUG_DEVTOOLS_ALLOCATIONS=normal|verbose,
but still record allocation count as DAMP subtests as that's easier to read.
Also, it would ease pushing custom builds to keep track of memory consumption over time.
I would like to push to try manually once a month or something to see how this data is evolving.

> But for the logging part, shared-head and damp could just check that
> DEBUG_ALLOCATIONS is set to something and let the helper decide what to log
> depending on the value of the environment variable.
> That would reduce a bit the consumed API of the helper in our real code.

I think it will be important to be able to use this helper manually
if you want to track a very specific code, a subpart of a mochitest
or some internal within tool implementation.
I added documentation about that in the helper header.

> Regarding the name of the variables, maybe we should mention DEVTOOLS in
> their names? eg. DEBUG_DEVTOOLS_ALLOCATIONS

Renamed.

> 
> ::: devtools/shared/moz.build:36
> (Diff revision 4)
> >      'transport',
> >      'webconsole',
> >      'worker',
> >  ]
> >  
> > +DIRS += ['test-helpers']
> 
> Should be for local builds only?

Yes! DAMP still works fine locally with a fix here.

> ::: testing/talos/talos/tests/devtools/addon/content/damp.js:260
> (Diff revision 4)
> > +        if (COUNT_ALLOCATIONS) {
> > +          this._results.push({
> > +            name: label + ".allocations",
> > +            value: this.allocationTracker.countAllocations()
> > +          });
> 
> Since it will not actually run on CI, I'm not convinced we should push the
> results here.

I keep doing that as I find it easier to read and would ease me pushing custom build to track this data over time.

> ::: testing/talos/talos/tests/devtools/addon/content/damp.js:1126
> (Diff revision 4)
> >      // Free memory before running the first test, otherwise we may have a GC
> >      // related to Firefox startup or DAMP setup during the first test.
> >      garbageCollect().then(() => {
> >        this._doSequence(sequenceArray, this._doneInternal);
> > +    }, e => {
> > +      dump("Exception while running DAMP tests: " + e + "\n" + e.stack + "\n");
> 
> I'm always confused by then()'s second argument, but I think this will only
> catch errors from garbageCollect() right? Use .catch() to better match the
> error description.

Good "catch"! ;)

Comment 16

[Alexandre Poirot [:ochameau]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

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

Comment 17

[Julian Descottes [:jdescottes]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

https://reviewboard.mozilla.org/r/205842/#review219970

LGTM, some nits and comments.

The reason I suggested using DEBUG_DEVTOOLS_ALLOCATIONS with different values was really to encapsulate all the logging logic in the tracker. 
If the consumers still have to decide what to do based on the value of the varibale, then I don't have a strong preference between using two different variables or using different values for a single variable.
(just mentioning this in case you prefer to go back to your previous approach with DEBUG & COUNT variables)

::: devtools/client/framework/test/shared-head.js:103
(Diff revision 5)
>  registerCleanupFunction(() => {
>    Services.obs.removeObserver(ConsoleObserver, "console-api-log-event");
>  });
>  
> +// Print allocation count if DEBUG_DEVTOOLS_ALLOCATIONS is set to "normal",
> +// and allocation sites if DEBUG_ALLOCATIONS is set to "verbose".

DEBUG_DEVTOOLS_ALLOCATIONS

::: devtools/client/framework/test/shared-head.js:106
(Diff revision 5)
>  
> +// Print allocation count if DEBUG_DEVTOOLS_ALLOCATIONS is set to "normal",
> +// and allocation sites if DEBUG_ALLOCATIONS is set to "verbose".
> +const env = Cc["@mozilla.org/process/environment;1"].getService(Ci.nsIEnvironment);
> +const DEBUG_ALLOCATIONS = env.get("DEBUG_DEVTOOLS_ALLOCATIONS");
> +if (DEBUG_ALLOCATIONS == "normal" || DEBUG_ALLOCATIONS == "verbose") {

can this be swapped for if (DEBUG_ALLOCATIONS) ?

::: devtools/shared/test-helpers/moz.build:1
(Diff revision 5)
>  # -*- Mode: python; indent-tabs-mode: nil; tab-width: 40 -*-

File is still seen as copied from devtools/shared/moz.build

::: devtools/shared/test-helpers/allocation-tracker.js:11
(Diff revision 5)
> + * This file helps tracking Javascript object allocations.
> + * It is only included in local builds as a debugging helper.
> + *
> + * It is typicaly used when running DevTools tests (either mochitests or DAMP).
> + * To use it, you need to set the following environment variable:
> + *   DEBUG_ALLOCATIONS="normal"

DEBUG_ALLOCATIONS -> DEBUG_DEVTOOLS_ALLOCATIONS

::: devtools/shared/test-helpers/allocation-tracker.js:12
(Diff revision 5)
> + *     This will only print the number of JS objects created during your test.
> + *   DEBUG_ALLOCATIONS="verbose"

ditto

(thanks for the doc otherwise, it's much easier to understand now!!)

::: devtools/shared/test-helpers/allocation-tracker.js:160
(Diff revision 5)
> +              // Compress the data to make it readable on stdout
> +              lines.push(line + ": " + count);
> +            });
> +          return { src, count: item.count, lines };
> +        });
> +      dump("Javascript object allocations: " + allocations.length + "\n" +

Users should know what to grep for when using the tracker. So we should mention "Javascript object allocations" is the thing to look for in the documentation of the file. Maybe use an all caps prefix such as "DEVTOOLS ALLOCATIONS" so that it stands out visually in the logs.

::: devtools/shared/test-helpers/allocation-tracker.js:179
(Diff revision 5)
> +    flushAllocations() {
> +      dbg.memory.drainAllocationsLog();
> +    },
> +
> +    stop() {
> +      dump("Stop logging allocations\n");

same remark about having a shared prefix for all dumps coming from this file.

::: testing/talos/talos/tests/devtools/addon/content/damp.js:243
(Diff revision 5)
>     *         and we should record its duration.
>     */
>    runTest(label) {
> +    if (DEBUG_ALLOCATIONS) {
> +      if (!this.allocationTracker) {
> +        this.allocationTracker = this.startAllocationTracker();

Should we stop the tracker at the end of the tests, as it was done in the previous patch?

Comment 18

[Alexandre Poirot [:ochameau]]

(In reply to Julian Descottes [:jdescottes][:julian] from comment #17)
> Comment on attachment 8934917 [details]
> Bug 1423517 - Helps tracking JS allocations when running DevTools tests.
> 
> https://reviewboard.mozilla.org/r/205842/#review219970
> 
> LGTM, some nits and comments.
> 
> The reason I suggested using DEBUG_DEVTOOLS_ALLOCATIONS with different
> values was really to encapsulate all the logging logic in the tracker.
> If the consumers still have to decide what to do based on the value of the
> varibale, then I don't have a strong preference between using two different
> variables or using different values for a single variable.
> (just mentioning this in case you prefer to go back to your previous
> approach with DEBUG & COUNT variables)

I don't have strong opinion on both flavors.

> ::: devtools/shared/test-helpers/moz.build:1
> (Diff revision 5)
> >  # -*- Mode: python; indent-tabs-mode: nil; tab-width: 40 -*-
> 
> File is still seen as copied from devtools/shared/moz.build

I thought I hacked cinnabar enough to fix that, I'll try again...

> ::: devtools/shared/test-helpers/allocation-tracker.js:160
> (Diff revision 5)
> > +              // Compress the data to make it readable on stdout
> > +              lines.push(line + ": " + count);
> > +            });
> > +          return { src, count: item.count, lines };
> > +        });
> > +      dump("Javascript object allocations: " + allocations.length + "\n" +
> 
> Users should know what to grep for when using the tracker. So we should
> mention "Javascript object allocations" is the thing to look for in the
> documentation of the file. Maybe use an all caps prefix such as "DEVTOOLS
> ALLOCATIONS" so that it stands out visually in the logs.

Added "DEVTOOLS ALLOCATIONS: " prefix to all dump calls and documented that.

> ::: testing/talos/talos/tests/devtools/addon/content/damp.js:243
> (Diff revision 5)
> >     *         and we should record its duration.
> >     */
> >    runTest(label) {
> > +    if (DEBUG_ALLOCATIONS) {
> > +      if (!this.allocationTracker) {
> > +        this.allocationTracker = this.startAllocationTracker();
> 
> Should we stop the tracker at the end of the tests, as it was done in the
> previous patch?

It is better to create a Debugger instance only once. So I added some code to stop it on DAMP's end only.

Comment 19

[Alexandre Poirot [:ochameau]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

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

Comment 20

[Alexandre Poirot [:ochameau]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

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

Comment 21

[Alexandre Poirot [:ochameau]]

Comment on attachment 8934917 [details]
Bug 1423517 - Helps tracking JS allocations when running DevTools tests.

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

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c6432ace601d
Helps tracking JS allocations when running DevTools tests. r=jdescottes

Comment 23

[Dorel Luca [:dluca]]

https://hg.mozilla.org/mozilla-central/rev/c6432ace601d