Bugzilla

Comment 17

•

3 years ago

From bug 1719324:

(In reply to Gabriele Svelto [:gsvelto] from comment #6)

Yes, this is an OOM crash where the xul.dll library was unloaded (hence the useless stack). Specifically the allocation that failed was ~300KiB in size and it failed because we most likely ran out of address space; there was only ~172MiB left of it and it was probably heavily fragmented at that point. Given this is a 32-bit build it's likely that the process was pushing the boundaries of what we can do in the 2GiB of available address space.

Updated

•

3 years ago

Crash Signature: [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] → [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7]

Jared Wein [:jaws] (please needinfo? me)

Updated

•

3 years ago

Crash Signature: [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7] → [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7] [@ xul.dll + 0x2530c7e]

Florian Quèze [:florian]

Comment 18

•

3 years ago

Maybe we could profile these tests with the nativeallocations feature enabled to see where they are allocating (or retaining) memory.

That would be something like: MOZ_PROFILER_STARTUP_FEATURES=js,stackwalk,cpu,nativeallocations MOZ_PROFILER_STARTUP_ENTRIES=1000000000 ./mach test browser/components/preferences/tests/ --profiler

1000000000 is an arbitrary large value, the actual maximum buffer size is 2GB, which is probably not enough to profile the entire folder, so you might want to stop the run at some point (just quit the browser)

Crash Signature: [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7] [@ xul.dll + 0x2530c7e] → [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7] [@ xul.dll + 0x2530c7e]

Flags: needinfo?(gijskruitbosch+bugs)

Updated

•

3 years ago

Priority: -- → P3

Updated

•

3 years ago

Crash Signature: [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7] [@ xul.dll + 0x2530c7e] → [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7] [@ xul.dll + 0x2530c7e] [@ xul.dll + 0x12f028]

Updated

•

3 years ago

Crash Signature: [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7] [@ xul.dll + 0x2530c7e] [@ xul.dll + 0x12f028] → [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7] [@ xul.dll + 0x2530c7e] [@ xul.dll + 0x12f028] [@ xul.dll + 0x38d8aa0]

Updated

•

3 years ago

Crash Signature: [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7] [@ xul.dll + 0x2530c7e] [@ xul.dll + 0x12f028] [@ xul.dll + 0x38d8aa0] → [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7] [@ xul.dll + 0x2530c7e] [@ xul.dll + 0x12f028] [@ xul.dll + 0x38d8aa0] [@ xul.dll + 0x83e6a]

Atila Butkovits

Updated

•

3 years ago

Updated

•

3 years ago

Updated

•

3 years ago

Crash Signature: [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7] [@ xul.dll + 0x2530c7e] [@ xul.dll + 0x12f028] [@ xul.dll + 0x38d8aa0] [@ xul.dll + 0x83e6a] → [@ moz_xmalloc(unsigned int)], [@ mozalloc_handle_oom(unsigned int)] [@ xul.dll + 0x19666a7] [@ xul.dll + 0x2530c7e] [@ xul.dll + 0x12f028] [@ xul.dll + 0x38d8aa0] [@ xul.dll + 0x83e6a]

Summary: Intermittent windows7-32-shippable-qr browser/components/preferences/tests/<test> | application terminated with exit code 1 | application crashed [@ mozalloc_handle_oom(unsigned int)/moz_xmalloc(unsigned int)] → Intermittent windows7-32-qr browser/components/preferences/tests/<test> | application terminated with exit code 1 | application crashed [@ mozalloc_handle_oom(unsigned int)/moz_xmalloc(unsigned int)]

Comment hidden (Intermittent Failures Robot)

Comment 22

•

3 years ago

(In reply to Florian Quèze [:florian] (PTO until Aug 23) from comment #18)

Maybe we could profile these tests with the nativeallocations feature enabled to see where they are allocating (or retaining) memory.

That would be something like: MOZ_PROFILER_STARTUP_FEATURES=js,stackwalk,cpu,nativeallocations MOZ_PROFILER_STARTUP_ENTRIES=1000000000 ./mach test browser/components/preferences/tests/ --profiler

1000000000 is an arbitrary large value, the actual maximum buffer size is 2GB, which is probably not enough to profile the entire folder, so you might want to stop the run at some point (just quit the browser)

First of all, we really want browser.ini added to the path, or it runs the main dir and the siteData subdirectory separately which messes things up.

Still, this doesn't appear to work for me. In some cases the browser crashes, in other cases the profile doesn't symbolicate. I've now tried about 10 times, quitting the browser initially not at all (caused crashes), then after 1 minute, then progressively shorter intervals. Still, the symbolication issue doesn't go away:

profiler ERROR Encountered an exception during profile symbolication
profiler ERROR 'charmap' codec can't decode byte 0x9d in position 116223574: character maps to <undefined>

which means the results are not very useful: https://share.firefox.dev/3xtAZAV

As far as I can tell, the memory track thinks the main process retained about 400mb of memory. Which is weird, because the retained memory data source only tracks about 200mb of memory, so I don't understand where the other half is.

Of the 200mb, when looking at the JS view because the C++ symbols are useless, the biggest culprit (some 75mb) is AsyncShutdown - which is pretty confusing because presumably that's all from me manually quitting the browser, which wouldn't happen if the tests just completed. Of everything else, if I invert call trees, I see a few mb for different DOM and JS APIs, but nothing really jumps out - not to the point where we should be stuck for memory. This despite the fact that the commandline output does indicate memory use grows significantly while running the tests, from:

 0:15.10 GECKO(15984) MEMORY STAT | vsize 2104582MB | vsizeMaxContiguous 65537938MB | residentFast 496MB | heapAllocated 332MB

after the first one to:

 0:41.06 GECKO(15984) MEMORY STAT | vsize 2106082MB | vsizeMaxContiguous 65537938MB | residentFast 1354MB | heapAllocated 1112MB

right before quitting.

The final thing that is odd is that I would expect that any DOM/JS stuff inside about:preferences gets cleared out by GCs, but on the retained memory event source, if I select some of the methods listed as having retained memory, it highlights things on the timeline from very early in the run, which (assuming the highlighting is accurate in terms of which calls to these functions/methods allocated the retained memory) suggests we haven't deallocated the relevant DOM/JS bits yet, which I find surprising. But I don't know how to get any more information about why that is from the profile or the tests.

Florian is out for the next 2 weeks; :mccr8, or gerald, do you think you might be in a position to help here?

I suspect fixing bug 1533771 may help here, but that also feels like it might wallpaper the "real" issues here.

Flags: needinfo?(gsquelart)

Flags: needinfo?(gijskruitbosch+bugs)

Flags: needinfo?(continuation)

Comment 23

•

3 years ago

Looking at the MEMORY STAT values that continue as the directory runs, it starts out around 223MB of heapAllocated. As the tests go on, this changes by anywhere from -50MB to 30MB. It isn't climbing up monotonically, but it is definitely more up than down.

I can take a look. I'm going to log all CCs, then look in later logs for anything that seems like it is from an earlier test, likely through the advanced technique of grepping for the name of the test.

Flags: needinfo?(continuation)

Comment 24

•

3 years ago

Ok, looking for a test name didn't help much.

Next, I ran my census.py script on the GC logs, comparing an early log to a late log (where the size of the later log dropped a bunch compared to the previous one, so hopefully there's no as much garbage in it. The most common script, chrome://browser/content/preferences/main.js, had around 4300 instances in the early log (4), and about 11,800 in the later log (41).

I then grepped the logs for these scripts, filtered by whether they are black (B) which means they are currently active, or grey (G) which means they are only being held alive via C++.

The number of "active" scripts is about the same:

> grep "B script chrome://browser/content/preferences/main.js" gc-edges.6171-4.log | wc
    2145    8580  157954
> grep "B script chrome://browser/content/preferences/main.js" gc-edges.6171-41.log | wc
    2852   11408  209449

But the number of "inactive" scripts has really increased:

> grep "G script chrome://browser/content/preferences/main.js" gc-edges.6171-4.log | wc 
    1443    5772  106122
> grep "G script chrome://browser/content/preferences/main.js" gc-edges.6171-41.log | wc
    8596   34384  631731

There's also a large increase in the number of copies of functions named MozButtonBase/< chrome://global/content/elements/button.js (from about 4800 to 12000) and about a doubling in the number of copies of functions named MozCheckbox/< chrome://global/content/elements/checkbox.js.

I'll see if I can figure out what is holding alive the grey main.js scripts.

Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)

Comment 25

•

3 years ago

It does look like the grey scripts are periodically being cleaned up completely. I guess I need to figure out what changed to make it so we cleaned them up. I just looked at a chain of about 12 logs where the number of main.js scripts creeped up from about 3200 to 5600, then dropped to 357.

Comment 26

•

3 years ago

(In reply to :Gijs (he/him) from comment #22)

Still, this doesn't appear to work for me. In some cases the browser crashes, in other cases the profile doesn't symbolicate. I've now tried about 10 times, quitting the browser initially not at all (caused crashes), then after 1 minute, then progressively shorter intervals. Still, the symbolication issue doesn't go away:
profiler ERROR Encountered an exception during profile symbolication
profiler ERROR 'charmap' codec can't decode byte 0x9d in position 116223574: character maps to <undefined>
which means the results are not very useful: https://share.firefox.dev/3xtAZAV

One quick trick you could try: Add MOZ_PROFILER_SYMBOLICATE=1 to your command line, it does symbolication a different way, directly inside Firefox -- note that will freeze Firefox for a few (lots of) seconds when you capture/quit.

NI -> Markus, who knows more/everything about profiler symbolication.

(And I can't give useful advice regarding the memory issue being investigated. Good luck!)

Flags: needinfo?(gsquelart) → needinfo?(mstange.moz)

Markus Stange [:mstange]

Comment 27

•

3 years ago

(In reply to :Gijs (he/him) from comment #22)

profiler ERROR Encountered an exception during profile symbolication
profiler ERROR 'charmap' codec can't decode byte 0x9d in position 116223574: character maps to <undefined>

This error probably comes from the python scripts that try to do the symbolication. I'm not very familiar with those.

Gijs, as a workaround, you could try to do the following:

cargo install profiler-symbol-server
profiler-symbol-server yourprofile.json

And then maybe you'll need to go to the Profile Info panel and forcefully re-trigger symbolication, if it doesn't happen automatically.

Flags: needinfo?(mstange.moz)

Markus Stange [:mstange]

Comment 28

•

3 years ago

(In reply to :Gijs (he/him) from comment #22)

As far as I can tell, the memory track thinks the main process retained about 400mb of memory. Which is weird, because the retained memory data source only tracks about 200mb of memory, so I don't understand where the other half is.

Indeed, this looks odd. It's suspicious that it's exactly half.

Of everything else, if I invert call trees, I see a few mb for different DOM and JS APIs, but nothing really jumps out

Nothing jumps out in the memory track, either - there are no big steps.

This despite the fact that the commandline output does indicate memory use grows significantly while running the tests, from:
 0:15.10 GECKO(15984) MEMORY STAT | vsize 2104582MB | vsizeMaxContiguous 65537938MB | residentFast 496MB | heapAllocated 332MB
after the first one to:
 0:41.06 GECKO(15984) MEMORY STAT | vsize 2106082MB | vsizeMaxContiguous 65537938MB | residentFast 1354MB | heapAllocated 1112MB
right before quitting.

That's a much larger increase that what the memory track shows, which only goes to 400MB of explicit allocations. Weird.

(assuming the highlighting is accurate in terms of which calls to these functions/methods allocated the retained memory)

I think it's accurate in the sense that it shows where the same stacks were observed, as the ones that allocated memory. But it doesn't mean that the stack allocated a lot of memory in the highlighted places, just that the same stacks ran at those times. I guess it would be useful to be able to select a stack and then see a graph of when most of that stack's retained memory was allocated.

Comment hidden (Intermittent Failures Robot)

Comment 30

•

3 years ago

Thanks Markus and Gerald for the profiler tips. I'm going to re-add the needinfo for reasons that will become apparent shortly...

(In reply to Gerald Squelart [:gerald] (he/him) from comment #26)

One quick trick you could try: Add MOZ_PROFILER_SYMBOLICATE=1 to your command line, it does symbolication a different way, directly inside Firefox -- note that will freeze Firefox for a few (lots of) seconds when you capture/quit.

This appears to cause Firefox to hang / get confused at startup. It just sits there in the task manager, taking no CPU and only 1MB of RAM, doing nothing (last output on the commandline is Started process `GECKO(pid)`, and then nothing happens).

Should I file a bug? Where do I start? :-)

(In reply to Markus Stange [:mstange] from comment #27)

(In reply to :Gijs (he/him) from comment #22)
profiler ERROR Encountered an exception during profile symbolication
profiler ERROR 'charmap' codec can't decode byte 0x9d in position 116223574: character maps to <undefined>
This error probably comes from the python scripts that try to do the symbolication. I'm not very familiar with those.

Gijs, as a workaround, you could try to do the following:
cargo install profiler-symbol-server
profiler-symbol-server yourprofile.json
And then maybe you'll need to go to the Profile Info panel and forcefully re-trigger symbolication, if it doesn't happen automatically.

OK, fwiw, it took me a few tries to even get a file out of the profiler (I tried using MOZ_PROFILER_SHUTDOWN=path which didn't work; I tried using the file path that mochitest outputs, which also didn't work (apparently gets removed as soon as it's handed off to the profiler).
I then tried using --profiler-save-only in combination with setting MOZ_UPLOAD_DIR, which appears to have worked. Then I tried to install profiler-symbol-server in order to follow your steps, but it doesn't compile, because it uses std::os::Unix::io in src/filedescriptor.rs, in core-foundation-0.9.1, and I'm trying this on Windows^^. Then there's more errors that it can't find RawFd and PATH_MAX. I don't know how to fix that. Is there an alternative that works on Windows, or am I just going to want to run these steps on macOS and hope whatever we find accurately indicates where the problems are on Windows?

^^ in part because that's where the issue is (though I'm testing on Win10) and in part because I have a much beefier Windows machine than my macbook...

Flags: needinfo?(mstange.moz)

Flags: needinfo?(gsquelart)

Markus Stange [:mstange]

Comment 31

•

3 years ago

(In reply to :Gijs (he/him) from comment #30)

Then I tried to install profiler-symbol-server in order to follow your steps, but it doesn't compile, because it uses std::os::Unix::io in src/filedescriptor.rs, in core-foundation-0.9.1, and I'm trying this on Windows^^.

Sorry about that. I've pushed a fix. cargo install profiler-symbol-server now works on Windows.

Flags: needinfo?(mstange.moz)

Comment 32

•

3 years ago

(In reply to Markus Stange [:mstange] from comment #31)

(In reply to :Gijs (he/him) from comment #30)

Then I tried to install profiler-symbol-server in order to follow your steps, but it doesn't compile, because it uses std::os::Unix::io in src/filedescriptor.rs, in core-foundation-0.9.1, and I'm trying this on Windows^^.

Sorry about that. I've pushed a fix. cargo install profiler-symbol-server now works on Windows.

Thanks, this helped! I now have https://share.firefox.dev/3CCGW2j which is symbolicated, but I'm still about as puzzled as before about the contents of the profile... Though one odd thing I did find is how about:newtab's AboutPreferences.jsm's setupUserEvent call is apparently responsible for 1.3mb of retained memory (https://share.firefox.dev/3jJdjnp), more than all the other CE bindings or whatever? That seems like a lot, but still it's peanuts compared to the total numbers we're talking about, so I continue to be confused. :-(

(In reply to Andrew McCreight [:mccr8] from comment #25)

It does look like the grey scripts are periodically being cleaned up completely. I guess I need to figure out what changed to make it so we cleaned them up. I just looked at a chain of about 12 logs where the number of main.js scripts creeped up from about 3200 to 5600, then dropped to 357.

Is it possible there is some async task that outlives the about:preferences windows "for a while" and causes all this to stick around, until the task finishes? And because of how fast the tests run, we just accrue a bunch of such nearly-but-not-quite dead windows, and that adds up, or something? If so, is there a straightforward way of finding out what task that is?

Flags: needinfo?(gsquelart) → needinfo?(continuation)

Comment 33

•

3 years ago

I was able to look at this some more today. I wrote a Python script to analyze what happens to the various preferences/main.js scripts from one GC log to the next. Mostly this confirmed what I said before. From log 14 to 15, about 4500 black scripts remain black and 4300 grey remain grey. Then in the next one practically every black script becomes grey. Then all of the grey scripts are cleaned up. I picked about a half dozen different black script objects that turned grey from 15 to 16, and looked up why they were black.

I'll attach the log, but unfortunately there's no real commonality that I can see. There's some cacheir-object edges in there that looks suspicious to me, but maybe that's normal now?

Comment 34

•

3 years ago

Attached file paths keeping alive some of the JS scripts that soon go away — Details

Comment hidden (Intermittent Failures Robot)

Comment 36

•

3 years ago

Jan, what's with these cacheir-shape edges? Do they keep stuff alive for awhile (like some of the old JIT cache things that got purged only on major GCs)?

Flags: needinfo?(jdemooij)

Updated

•

3 years ago

Flags: needinfo?(continuation)

Assignee

Comment 37

•

3 years ago

(In reply to Andrew McCreight [:mccr8] from comment #36)

Jan, what's with these cacheir-shape edges? Do they keep stuff alive for awhile (like some of the old JIT cache things that got purged only on major GCs)?

Yeah exactly, these are shapes stored in JIT IC stubs. Shapes have a realm and keep that realm's global alive. We purge JIT code and IC stubs on major GCs based on some heuristics. Ideally these IC edges would be weak, but it's complicated...

It's possible we could improve our JIT/IC discarding heuristics, but would that help here? Reading your comments it sounds like we do collect most of the garbage pretty quickly.

Flags: needinfo?(continuation)

Andreea Pavel [:apavel]

Updated

•

3 years ago

Whiteboard: [stockwell needswork:owner]

Comment 38

•

3 years ago

(In reply to Jan de Mooij [:jandem] from comment #37)

It's possible we could improve our JIT/IC discarding heuristics, but would that help here? Reading your comments it sounds like we do collect most of the garbage pretty quickly.

Well, something, possibly this JIT IC thing, is keeping stuff around long enough that we are frequently OOMing on Win32 in this specific test directory. The general GC/CC issue we have with tests is that they create and destroy lots of DOM stuff very quickly, so time based heuristics often don't do well.

Flags: needinfo?(continuation)

Comment 39

•

3 years ago

(In reply to Andrew McCreight [:mccr8] from comment #38)

(In reply to Jan de Mooij [:jandem] from comment #37)

It's possible we could improve our JIT/IC discarding heuristics, but would that help here? Reading your comments it sounds like we do collect most of the garbage pretty quickly.

Well, something, possibly this JIT IC thing, is keeping stuff around long enough that we are frequently OOMing on Win32 in this specific test directory. The general GC/CC issue we have with tests is that they create and destroy lots of DOM stuff very quickly, so time based heuristics often don't do well.

If we're convinced that the GC/CC behaviour here is proper and there isn't a lurking issue with prefs or other code-under-test causing leaks, then perhaps we should just have the head.js file here add a clean up function that forces a GC/CC? Presumably that would address the OOM conditions...

Assignee

Comment 40

•

3 years ago

I'll take a look at our JIT code discarding heuristics to see if there's something we can do there.

Comment 41

•

3 years ago

(In reply to :Gijs (he/him) from comment #39)

If we're convinced that the GC/CC behaviour here is proper and there isn't a lurking issue with prefs or other code-under-test causing leaks, then perhaps we should just have the head.js file here add a clean up function that forces a GC/CC? Presumably that would address the OOM conditions...

We're already doing a bunch of GCs/CCs, I believe. The problem is that this isn't enough for some reason, possibly because JIT memory isn't being freed. Maybe we could force a compacting GC or something, though GCing too much can slow things down a lot, and generally I try to avoid doing non-incremental GCs because then we have less testing for incremental GC, which is what we use most of the time. Of course, for just a single directory that's not as much of a concern.

Assignee

Comment 42

•

3 years ago

I confirmed this has to do with our JIT code discarding heuristics. I'm testing a fix for this.

Assignee

Comment 43

•

3 years ago

Attached file Bug 1717917 - Don't delay discarding JIT code for more than 30 seconds when animating. r?jonco! — Details

This fixes frequent OOMs on Win32 when running about:preferences tests.

THe problem is that we don't discard JIT code frequently enough if we keep being
notified of animations. This resulted in leaking global objects via Baseline
IC stubs, likely because we keep loading things in the system zone. This patch
changes the heuristic to ignore the animation hint if the last code discard was
more than 30 seconds ago.

This is all quite brittle unfortunately and these heuristics should probably be
redone at some point as part of a bigger project.

Phabricator Automation

Updated

•

3 years ago

Assignee: nobody → jdemooij

Status: NEW → ASSIGNED

Assignee

Updated

•

3 years ago

Flags: needinfo?(jdemooij)

Pulsebot

Comment 44

•

3 years ago

Pushed by jdemooij@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/6f20e462bf19
Don't delay discarding JIT code for more than 30 seconds when animating. r=jonco

https://hg.mozilla.org/mozilla-central/rev/6f20e462bf19

Comment 45

•

3 years ago

Thanks for the fix, Jan!

Marian-Vasile Laza

Comment 46

•

3 years ago

bugherder

Status: ASSIGNED → RESOLVED

Closed: 3 years ago

status-firefox93: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → 93 Branch

Comment hidden (Intermittent Failures Robot)

Andra Esanu (needinfo me)

Comment 48

•

3 years ago

== Change summary for alert #31000 (as of Mon, 23 Aug 2021 06:10:32 GMT) ==

Improvements:

Ratio	Test	Platform	Options	Absolute values (old vs new)
27%	tp5o_webext responsiveness	windows10-64-shippable-qr	e10s stylo webrender	2.06 -> 1.51
25%	tp5o_webext responsiveness	windows10-64-shippable-qr	e10s stylo webrender-sw	1.96 -> 1.47
14%	tp5o_webext responsiveness	linux1804-64-shippable-qr	e10s stylo webrender-sw	5.69 -> 4.91
14%	tp5o_webext responsiveness	linux1804-64-shippable-qr	e10s stylo webrender-sw	5.58 -> 4.82
13%	tp5o_webext responsiveness	linux1804-64-shippable-qr	e10s stylo webrender	5.50 -> 4.77
12%	tp5o_webext responsiveness	linux1804-64-shippable-qr	e10s stylo webrender-sw	5.56 -> 4.92

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

Andra Esanu (needinfo me)

Updated

•

3 years ago

Keywords: perf-alert