1420303 - Reduce DAMP variance by doing GC between tests

Status: RESOLVED FIXED

(DevTools :: General, enhancement, P2)

Description

[Alexandre Poirot [:ochameau]]

A good start to reduce DAMP variance would be to start forcing some GC at critical steps.

Based on profiler results, with markers from bug 1420233:
https://perfht.ml/2mXLsFO

It becomes clear that GC from previous tests happen during the following tests in most cases. It makes the test having high variations as these GC happens at random timings and are not necesarrely always of the same size/duration.

There is one first obvious spot to put a GC.
At test teardown. At least it cleans up each subtest before running the next one.
Then, you can see a significant GC happening during the first subtest, cold.inspector.open. This is most likely a GC due to Firefox startup or DAMP setup.
And finally, there is often a GC during "reload" subtest, especially during "complicated" subtests. So it may help to do a GC after "open" subtests.

I tried adding only GC at startup and on test teardown:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=mozilla-central&newProject=try&newRevision=0fee79871954faccbd08982ee5ab9d0cd59a441c&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&framework=1&selectedTimeRange=172800
The variance is cut by half (-50.51% thanks to new PerfHerder noise computation) 
and DAMP runs in 43minutes

Then I tried these GC and also between open and reload subtests:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=mozilla-central&newProject=try&newRevision=91498e7d44fca8cf087521a3fc9cdde6516da441&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&framework=1&selectedTimeRange=172800
This time the various is -69.35% better and DAMP runs in 48minutes
With this patch you get this profile:
  https://perfht.ml/2hOgUkI
Where (major) GC rarely happen during a test!


So DAMP today, runs in 35minutes. I think it is really worth increasing its running time for a significantly better noise factor!
We can followup to stop running DAMP *and* tps tests in the same job. It would save 6-7 minutes. We could also look into splitting DAMP in more than one job, but I'm expecting that to be slightly harder.

Comment 1

[Alexandre Poirot [:ochameau]]

Attachment: Bug 1420303 - Free memory between DAMP test to reduce its noise factor.

Doing one GC before running all test prevent having one running during the first test.
Doing another on test teardown prevent getting another during next subtests.
And finally, doing a last one after toolbox opening prevent a major GC from running during reload tests (especially "complicated" ones).

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

Comment 2

[Alexandre Poirot [:ochameau]]

Some more stats about this. Here is the numbers I have been using over bug 1407826.

With this patch,
  average stddev is 1.52
  max stdev is 8%
  stddev sum is 93

On mozilla-central, today, it is:
  average stddev is 4.43
  max stddev is 22%
  stddev sum is 257

(With only GC on teardown [so without the GC after toolbox open]:
  average = 2.17
  max = 12%
  sum = 132)

Comment 3

[Julian Descottes [:jdescottes]]

Comment on attachment 8931533 [details]
Bug 1420303 - Free memory between DAMP test to reduce its noise factor.

https://reviewboard.mozilla.org/r/202652/#review208900

The reduced noise is great, but why do we get a ~20% slowdown for the DAMP summary?

I think we should go for it regardless, because it will make our tests easier to maintain and work on. 
But it would be nice to understand why we perform a bit worst after a GC. Is it because it gets slower to allocate new space for our objects right after the GC?

::: testing/talos/talos/tests/devtools/addon/content/damp.js:45
(Diff revision 1)
> +function garbageCollect() {
> +  dump("Garbage collect\n");
> +
> +  // Minimize memory usage
> +  //
> +  // This method ends up doing mutliple CC and GC.

nit: mutliple -> multiple

Comment 4

[Alexandre Poirot [:ochameau]]

(In reply to Julian Descottes [:jdescottes][:julian] from comment #3)
> Comment on attachment 8931533 [details]
> Bug 1420303 - Free memory between DAMP test to reduce its noise factor.
> 
> https://reviewboard.mozilla.org/r/202652/#review208900
> 
> The reduced noise is great, but why do we get a ~20% slowdown for the DAMP
> summary?
> 
> I think we should go for it regardless, because it will make our tests
> easier to maintain and work on. 
> But it would be nice to understand why we perform a bit worst after a GC. Is
> it because it gets slower to allocate new space for our objects right after
> the GC?

I found one explanation. minimizeMemoryUsage does a lot more than doing GC.
I flushes many internal caches everywhere.
So calling this method forces to reload many ressources.
(It dispatches a "memory-pressure" event, which is observed in many many places:
 https://searchfox.org/mozilla-central/search?q=%22memory-pressure%22&path=)

So I tried another approach. I tried to mimic what minimizeMemoryUsage was doing,
but only on the GC, and got this result:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=2ed497c64dffa3fe9fbce0656d765e4caad3155f&newProject=try&newRevision=cb897a66f5041ec5a394b58b583c7d78e46aa532&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&framework=1
The noise is still greatly reduced: -53% per PerfHerder noise algorithm
Or here is the stats I'm using:
average stddev is 1.78%, max is 7% and sum is 137.
So in term of noise, it is almost as good as the previous patch.

DAMP summary reports no change, whereas the subtests are still impacted a lot with this patch.

I did a diff between the two patches:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=91498e7d44fc&newProject=try&newRevision=cb897a66f5041ec5a394b58b583c7d78e46aa532&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyImportant=1&framework=1
This comparison isn't totally fair as the two changeset were based on different m-c changeset,
but it still highlights that the new patch has a smaller impact. Especially on simple.* tests.

Comment 5

[Alexandre Poirot [:ochameau]]

Comment on attachment 8931533 [details]
Bug 1420303 - Free memory between DAMP test to reduce its noise factor.

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

Comment 6

[Julian Descottes [:jdescottes]]

Comment on attachment 8931533 [details]
Bug 1420303 - Free memory between DAMP test to reduce its noise factor.

https://reviewboard.mozilla.org/r/202652/#review209482

Great! Thanks for finding out the root cause of the slowdown.

::: testing/talos/talos/tests/devtools/addon/content/damp.js:44
(Diff revision 2)
>  
> +async function garbageCollect() {
> +  dump("Garbage collect\n");
> +
> +  // Minimize memory usage
> +  // mimic miminizeMemoryUsage, without flushing all caching, but only flushing JS objects.

Maybe add that we don't want to flush all caching because it badly impacts performances.

Comment 7

[Alexandre Poirot [:ochameau]]

Comment on attachment 8931533 [details]
Bug 1420303 - Free memory between DAMP test to reduce its noise factor.

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

Comment 8

[Alexandre Poirot [:ochameau]]

(In reply to Julian Descottes [:jdescottes][:julian] from comment #6)
> Maybe add that we don't want to flush all caching because it badly impacts
> performances.

Done. Also added permalink to platform code to justify the 3 iterations and the 3 GC/CC.

Comment 9

[Alexandre Poirot [:ochameau]]

Comment on attachment 8931533 [details]
Bug 1420303 - Free memory between DAMP test to reduce its noise factor.

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

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/bccb2ae0fd78
Free memory between DAMP test to reduce its noise factor. r=jdescottes

Comment 11

[Cristian Brindusan [:cbrindusan]]

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

Comment 12

[Joel Maher ( :jmaher ) (UTC -8)]

Thanks for getting this landed, there are some perf differences we see with this change:
== Change summary for alert #10819 (as of Thu, 30 Nov 2017 18:40:08 GMT) ==

Regressions:

  6%  damp windows7-32 opt e10s     316.40 -> 335.66
  5%  damp osx-10-10 opt e10s       340.81 -> 358.72
  5%  damp windows7-32 pgo e10s     253.05 -> 265.80
  4%  damp windows10-64 opt e10s    298.94 -> 312.16
  4%  damp linux64 pgo e10s         281.57 -> 292.10
  4%  damp windows10-64 pgo e10s    254.55 -> 263.82
  4%  damp linux64 opt e10s         312.77 -> 323.85

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=10819

:ochameau, do these changes in reported values look correct?