1729890 - 7.76 - 3.24% Explicit Memory / Heap Unclassified + 14 more (Linux, OSX, Windows) regression on Tue September 7 2021

Status: RESOLVED FIXED

(Core :: JavaScript: GC, defect)

Description

[Acasandrei Beatrice (needinfo me)]

Perfherder has detected a awsy performance regression from push 891ac85a6625cff469546795bcde4aca9db2a4c1. As author of one of the patches included in that push, we need your help to address this regression.

Regressions:

Ratio	Test	Platform	Options	Absolute values (old vs new)
8%	Explicit Memory	windows10-64-2004-shippable-qr	fission tp6	630,595,157.43 -> 679,549,100.43
8%	Explicit Memory	windows10-64-2004-shippable-qr	fission tp6	636,652,624.65 -> 685,425,600.17
7%	Explicit Memory	macosx1015-64-shippable-qr	fission tp6	658,811,461.16 -> 707,959,499.11
7%	Explicit Memory	windows10-64-2004-shippable-qr	tp6	673,222,929.13 -> 722,181,997.29
7%	Resident Memory	windows10-64-2004-shippable-qr	fission tp6	848,151,762.56 -> 904,550,369.29
7%	Explicit Memory	linux1804-64-shippable-qr	fission tp6	786,161,982.72 -> 837,966,420.08
7%	Resident Memory	windows10-64-2004-shippable-qr	fission tp6	848,594,952.29 -> 904,032,997.36
6%	Resident Memory	windows10-64-2004-shippable-qr	fission tp6	843,578,847.72 -> 897,380,588.82
6%	Resident Memory	windows10-64-2004-shippable-qr	tp6	904,591,744.59 -> 957,633,997.44
6%	Heap Unclassified	windows10-64-2004-shippable-qr	tp6	78,555,694.94 -> 83,143,584.12
...	...	...	...	...
5%	Heap Unclassified	windows10-64-2004-shippable-qr	fission tp6	88,242,519.16 -> 92,672,239.71
5%	Resident Memory	linux1804-64-shippable-qr	fission tp6	1,178,895,503.69 -> 1,236,880,424.08
5%	Heap Unclassified	windows10-64-2004-shippable-qr	fission tp6	87,829,516.62 -> 91,935,546.92
3%	Heap Unclassified	macosx1015-64-shippable-qr	fission tp6	133,384,800.77 -> 137,782,242.96
3%	Heap Unclassified	linux1804-64-shippable-qr	fission tp6	232,138,557.34 -> 239,649,401.17

Details of the alert can be found in the alert summary, including links to graphs and comparisons for each of the affected tests. Please follow our guide to handling regression bugs and let us know your plans within 3 business days, or the offending patch(es) will be backed out in accordance with our regression policy.

For more information on performance sheriffing please see our FAQ.

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1728273

Comment 2

[Alexandru Ionescu (needinfo me) [:alexandrui]]

== Change summary for alert #31208 (as of Wed, 08 Sep 2021 13:36:46 GMT) ==

Regressions:

Ratio	Test	Platform	Options	Absolute values (old vs new)
8%	facebook-cristiano dcf	android-hw-p2-8-0-android-aarch64-shippable-qr	warm webrender	283.44 -> 306.12

Improvements:

Ratio	Test	Platform	Options	Absolute values (old vs new)
3%	twitter LastVisualChange	linux1804-64-shippable-qr	cold fission webrender	2,945.00 -> 2,856.67

For up to date results, see: https://treeherder.mozilla.org/perfherder/alerts?id=31208

Comment 3

[Jon Coppeard (:jonco)]

It's really strange that making more GCs full GCs would increase memory usage. Just wondering if you have an idea of what's going on here Paul?

Comment 4

[Jon Coppeard (:jonco)]

Telemetry indicates that the patch in bug 1728273 is working:

https://glam.telemetry.mozilla.org/firefox/probe/gc_is_compartmental/explore?activeBuckets=%5B%22yes%22%5D&ref=20210907214756

Comment 5

[Ted Campbell [:tcampbell]]

A few notes as we investigated:

• The awsy subtest here is the "after tabs open" test rather than when GC is forced.
• For the measurement after the GC, there is no change in numbers.
• This is an increase in the explicit heap, but there is no change in JS heap.
• So it seems that we have a transient increase in memory (which still could be considered a defect)
• We wonder if the full-GC is throwing off the CC heuristics and we are somehow keeping old windows around longer than before?

Comment 6

[Andrew McCreight [:mccr8]]

If you look under artifacts, you can download the memory reports for After Tabs Open before and after the change and then use about:memory in your browser to diff them to see what the difference is.

Comment 7

[Ted Campbell [:tcampbell]]

Following advice in Comment 6.
Memory Report Before: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/K_3uQ2mETSSCbG-laC9O0g/runs/0/artifacts/public/test_info/memory-report-TabsOpen-0.json.gz
Memory Report After: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/dMvX_dTIT8O0zVwzA7QUTg/runs/0/artifacts/public/test_info/memory-report-TabsOpen-0.json.gz

Parent process adds 150 MB of heap unclassified (which is a subset of "explicit"). That seems to be the spike, but I'm not sure what is in it.

Comment 8

[Andrew McCreight [:mccr8]]

That is an oddly large amount of heap-unclassified. I wonder what we could be missing in terms of a reporter. There's some way to enable DMD with AWSY but I don't know how well it works. There's also an increase of 26MB of JS memory in the main process, 18MB increase with Gmail (in JS and some other stuff). Similarly for live.com.

Something definitely has gone wrong here. We're not cleaning up nearly as much stuff as normal for whatever reason. The forced GC passes true to the minimize memory usage argument to dumpMemoryReportsToNamedFile().

Comment 9

[Ted Campbell [:tcampbell]]

./mach awsy-test --tp6 --dmd --headless actually worked reasonably well. Something asserts at the end of the script, but I can still run dmd.py on the files in %OBJDIR%/_tests/awsy/results... and get what I need.

I see about 4000 HttpChannelParent instances taking in the TabsOpen checkpoint that are gone when the GC is forced. These seem to account for the bulk of the extra heap unclassified that we are seeing (10s of kB per channel adds up really fast when there are 4000 of them).

Comment 10

[Andrew McCreight [:mccr8]]

That's strange. I'm not sure what keeps those alive.

Comment 11

[Paul Bone [:pbone]]

(In reply to Jon Coppeard (:jonco) from comment #3)

It's really strange that making more GCs full GCs would increase memory usage. Just wondering if you have an idea of what's going on here Paul?

Thanks for lending a 2nd (& 3rd Ted!) set of eyes.

I was looking at the memory reports for and I see the difference appears to be in the bin-unused, which is the fragmentation of the jemalloc heap. But for any cause I could think of I expected to see a corresponding negative amount for some memory being freed. So I appriciate the extra eyes here.

I started with the Tabs Closed Settled memory reports and saw only this fragmentation. I was unable to get perfherder to show me the subtests due to Bug 1729057, which might have helped direct my search. So my best guess is like Ted said:

We wonder if the full-GC is throwing off the CC heuristics and we are somehow keeping old windows around longer than before?

I want to try messing with the patch to see what extra clues I can get. But I also want to try DMD like Ted did, that may be a more solid lead here.

Thanks everyone.

Comment 12

[Steve Fink [:sfink] [:s:]]

Another weirdness (not that we need more) in the pushes I did: although the heap unclassified numbers are fairly straightforward, saying that we're using a bunch of extra memory after tabs open up until it gets cleared out, the RSS numbers show the extra usage persisting after tabs close. Even in one case where it was temporarily better until tabs closed + 30s or + 30s+GC (at which point it was worse.)

It's almost like there was additional stuff to clean up during tab closing that loaded more stuff into memory? But RSS is always a weird measure, so maybe it's better not to speculate too much about it.

Comment 13

[Steve Fink [:sfink] [:s:]]

Note: I was running into bug 1729057 as well, but somehow the path I went through for the above links works. I clicked on "Compare with another revision" in treeherder, then filled in my try revs and selected awsy.

I will also note that unfortunately --gecko-profile-features does not appear to be implemented for awsy jobs. I wanted to get a marker-only profile out of it, but I didn't get a profile at all.

Comment 14

[Ted Campbell [:tcampbell]]

Here are some marker-only profiles
With Bug 1728273 Patch: https://share.firefox.dev/3Ad8hXg
Reverted: https://share.firefox.dev/39g2Smx

One thing that stands out is now few GCMajor happen in the parent process when the patch is there. There are none until the tabs start being closed. When I revert things, there are many GCs as the test case runs.

Comment 15

[Andrew McCreight [:mccr8]]

[Tracking Requested - why for this release]: very large regression on this memory test

Comment 16

[Paul Bone [:pbone]]

(In reply to Steve Fink [:sfink] [:s:] from comment #12)

Another weirdness (not that we need more) in the pushes I did: although the heap unclassified numbers are fairly straightforward, saying that we're using a bunch of extra memory after tabs open up until it gets cleared out, the RSS numbers show the extra usage persisting after tabs close. Even in one case where it was temporarily better until tabs closed + 30s or + 30s+GC (at which point it was worse.)

It's almost like there was additional stuff to clean up during tab closing that loaded more stuff into memory? But RSS is always a weird measure, so maybe it's better not to speculate too much about it.

I noticed that after tabs closed there was extra fragmentation in jemalloc's heap, probably due to stuff not being cleaned up earlier. Let's hope that goes away when we fix the main problem.

Comment 17

[Paul Bone [:pbone]]

I have requested a backout of Bug 1728273 which should fix this, but I'd rather check back and make sure the graph goes back down. Then I can look at other things in the short term and come back to this later.

Comment 18

[Paul Bone [:pbone]]

Looks like this got better. https://treeherder.mozilla.org/perfherder/alerts?id=31372