1699681 - Enabling the profiler with the JS feature to profile tests leaks windows until shutdown

Status: ASSIGNED

(Core :: Gecko Profiler, defect, P2)

Description

[Florian Quèze [:florian]]

Step to reproduce:
MOZ_PROFILER_STARTUP=1 MOZ_PROFILER_STARTUP_FEATURES="stackwalk,js" ./mach test browser/components/customizableui/test/browser_885530_showInPrivateBrowsing.js --headless

Result:
ERROR TEST-UNEXPECTED-FAIL | browser/components/customizableui/test/browser_885530_showInPrivateBrowsing.js | leaked 8 window(s) until shutdown [url = chrome://browser/content/browser.xhtml]
ERROR TEST-UNEXPECTED-FAIL | browser/components/customizableui/test/browser_885530_showInPrivateBrowsing.js | leaked 8 window(s) until shutdown [url = about:blank]

This behavior is not specific to the browser_885530_showInPrivateBrowsing.js test, many tests show this bug, but I've not verified if all of them reproduce. Some tests also leak docShells.

I'm using the MOZ_PROFILER_STARTUP_FEATURES environment variable here to reduce the feature set used, because using the I/O interposer triggers another leak.

Here are the various shutdown outcomes depending on the features used:

• "nostacksampling,js": Clean shutdown.
• "js": Shutdown leak of windows.
• "stackwalk", "nostacksampling": Shutdown crash on an assertion: MOZ_ASSERT(!mBufferPositionWhenReceivedJSContext) (JSContext should have been cleared before the thread was unregistered)

Comment 1

[Florian Quèze [:florian]]

A local backout of bug 1691504 fixes (or hides) this problem.

Comment 2

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

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

Comment 3

[Florian Quèze [:florian]]

I can still reproduce, and it's annoying as it makes the debugging automated tests with the profiler in debug builds very painful.

The "using the I/O interposer triggers another leak." part from comment 0 was fixed in bug 1699683.

Comment 4

[Florian Quèze [:florian]]

Actually, the leak also exists in non-debug builds, and almost made me blame the test I was profiling for a leak.
Profile with the default features: https://share.firefox.dev/3J2Fv2H an increasingly large amount of time is spent GC/CC'ing as the test (which uses a lot of windows) progresses.
Profile without the JS feature: https://share.firefox.dev/3QT6LCJ The same test now takes 30s instead of 46, and most of the GC/CC time is gone.

Comment 5

[Nazım Can Altınova [:canova][:canaltinova on phabricator]]

I spent some time to investigate this leak. Here are my findings:

It looks like the leak is not entirely Bug 1691504's fault. Before that bug was fixed, we weren't profiling the JIT samples properly, that's why probably all the JIT frames were missing before that patch.
After going down on that code path a bit, I realized that before that bug this branch was always executed instead of the code below. entry->isSampled(*rangeStart) was always producing false because of the wrong sample position in buffer. And since we negate that, it was always resulting in true and going in there.

So, it looks like it's about not expiring some of the JitcodeGlobalEntries properly. When I looked where we expire everything after the profiling session, I came across the profiler_clear_js_context API. This API calls JitcodeGlobalTable::setAllEntriesAsExpired method eventually by following the path below:
profiler_clear_js_context -> (StopJSSampling + PollJSSampling) -> EnableContextProfilingStack(mJSContext, false) -> GeckoProfilerRuntime::enable(false) -> JitcodeGlobalTable::setAllEntriesAsExpired.

In the end, my guess it is that either we are not calling the profiler_clear_js_context for some cases, or we are not calling it early enough during the shutdown.

When I looked at some JSContext destructors, I found that we are not calling this function inside nsJSContext::~nsJSContext. After adding it there, it seems like the leak is fixed!
But it's good to mention that my JS engine knowledge is really not that deep. I would like it if someone who knows JS engine better than me verifies that (probably I will send a WIP patch and ping people there).

Comment 6

[Nazım Can Altınova [:canova][:canaltinova on phabricator]]

Attachment: Bug 1699681 - Clear the JS context for profiler during nsJSContext destruction r?florian!,tcampbell!

During shutdown profiling, test suites were reporting window leaks on shutdown.
After investigating, I realized that we are not setting some
JitcodeGlobalEntries as expired. PROFILER_CLEAR_JS_CONTEXT sets these entries
as expired but it wasn't called in this case where we are destructing
nsJSContext.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/409858b7bb4a
Clear the JS context for profiler during nsJSContext destruction r=florian,sfink

Comment 8

[Atila Butkovits]

Backed out for causing failures at browser_test_feature_jsallocations.js.

Backout link: https://hg.mozilla.org/integration/autoland/rev/58ce88d4f5dab93d267c396fe01cd0b2ac706a57

Push with failures: https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&revision=409858b7bb4aa75debf041720f8a76dfd63bef92

Failure log: https://treeherder.mozilla.org/logviewer?job_id=405925394&repo=autoland&lineNumber=7292

Comment 9

[Acasandrei Beatrice (needinfo me)]

(In reply to Atila Butkovits from comment #8)

Backed out for causing failures at browser_test_feature_jsallocations.js.

Backout link: https://hg.mozilla.org/integration/autoland/rev/58ce88d4f5dab93d267c396fe01cd0b2ac706a57

Push with failures: https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&revision=409858b7bb4aa75debf041720f8a76dfd63bef92

Failure log: https://treeherder.mozilla.org/logviewer?job_id=405925394&repo=autoland&lineNumber=7292

== Change summary for alert #37242 (as of Mon, 20 Feb 2023 06:17:08 GMT) ==

Regressions:

Ratio	Test	Platform	Options	Absolute values (old vs new)
43%	perf_reftest_singletons style-attr-1.html	linux1804-64-shippable-qr	e10s fission stylo webrender	4.00 -> 5.72

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

Comment 10

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

There's a r+ patch which didn't land and no activity in this bug for 2 weeks.
:canova, could you have a look please?
If you still have some work to do, you can add an action "Plan Changes" in Phabricator.
For more information, please visit auto_nag documentation.