Long-running worker sometimes gets cycle-collected even though it still has listeners
Categories
(Core :: DOM: Workers, defect)
Tracking
()
People
(Reporter: mstange, Unassigned)
References
Details
This affects the Gecko profiler on local builds: Dumping symbols from xul.pdb can take a long time, and sometimes the worker that does the dumping just gets canceled before it has a chance to report its results.
Steps to reproduce:
- Obtain xul.dll, xul.pdb from a local Windows build.
- On any platform, open the browser console.
- Run the following code snippet:
Cu.import("resource://gre/modules/ProfilerGetSymbols.jsm");
await ProfilerGetSymbols.getSymbolTable("/path/to/xul.dll", "/path/to/xul.pdb", "5A19F8CB13AA091B4C4C44205044422E1");
(Adjust the breakpad ID to the one for the xul.pdb that you found.)
Expected results:
After about 7 seconds, some result should be printed: either an error or some JS value.
Actual results:
About one out of four times, the 7 seconds pass without anything happening, and the promise never fulfills.
I think I've managed to capture this in the debugger, in an opt build on macOS. It seems that the worker parent is canceling the worker during a cycle collection:
* thread #1, queue = 'com.apple.main-thread', stop reason = breakpoint 2.1
frame #0: 0x00000001152ee476 XUL`mozilla::dom::WorkerPrivate::Notify(this=0x0000000136231000, aStatus=Canceling) at WorkerPrivate.cpp:1572 [opt]
1569 AssertIsOnParentThread();
1570
1571 if (aStatus == Canceling) {
-> 1572 printf("%p GETTING CANCELED\n", this);
1573 }
1574
1575 bool pending;
Target 0: (firefox) stopped.
(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = breakpoint 2.1
* frame #0: 0x00000001152ee476 XUL`mozilla::dom::WorkerPrivate::Notify(this=0x0000000136231000, aStatus=Canceling) at WorkerPrivate.cpp:1572 [opt]
frame #1: 0x00000001152d9475 XUL`mozilla::dom::Worker::cycleCollection::Unlink(void*) [inlined] mozilla::dom::WorkerPrivate::Cancel(this=<unavailable>) at WorkerPrivate.h:141 [opt]
frame #2: 0x00000001152d946b XUL`mozilla::dom::Worker::cycleCollection::Unlink(void*) [inlined] mozilla::dom::Worker::Terminate(this=0x0000000136fc58b0) at Worker.cpp:147 [opt]
frame #3: 0x00000001152d945f XUL`mozilla::dom::Worker::cycleCollection::Unlink(this=<unavailable>, p=0x0000000136fc58b0) at Worker.cpp:161 [opt]
frame #4: 0x0000000112ca83fa XUL`nsCycleCollector::CollectWhite(this=0x0000000112821f00) at nsCycleCollector.cpp:3090 [opt]
frame #5: 0x0000000112ca92dd XUL`nsCycleCollector::Collect(this=0x0000000112821f00, aCCType=<unavailable>, aBudget=<unavailable>, aManualListener=<unavailable>, aPreferShorterSlices=<unavailable>) at nsCycleCollector.cpp:3436 [opt]
frame #6: 0x0000000112caaa21 XUL`nsCycleCollector_collectSlice(budget=0x00007fff56aced38, aPreferShorterSlices=false) at nsCycleCollector.cpp:3926 [opt]
frame #7: 0x0000000113f66f25 XUL`nsJSContext::RunCycleCollectorSlice(aDeadline=<unavailable>) at nsJSEnvironment.cpp:1596 [opt]
frame #8: 0x0000000113f686a1 XUL`CCRunnerFired(aDeadline=<unavailable>) at nsJSEnvironment.cpp:1875 [opt]
frame #9: 0x0000000112d23598 XUL`mozilla::IdleTaskRunner::Run() [inlined] std::__1::__function::__value_func<bool (mozilla::TimeStamp)>::operator(this=<unavailable>, __args=<unavailable>)(mozilla::TimeStamp&&) const at functional:1860 [opt]
frame #10: 0x0000000112d23581 XUL`mozilla::IdleTaskRunner::Run() [inlined] std::__1::function<bool (mozilla::TimeStamp)>::operator(this=<unavailable>, __arg=TimeStamp @ 0x00007fff56acee38)(mozilla::TimeStamp) const at functional:2419 [opt]
frame #11: 0x0000000112d23581 XUL`mozilla::IdleTaskRunner::Run(this=0x00000001419bb980) at IdleTaskRunner.cpp:58 [opt]
frame #12: 0x0000000112d38bc2 XUL`nsThread::ProcessNextEvent(this=0x000000011288c9e0, aMayWait=<unavailable>, aResult=<unavailable>) at nsThread.cpp:1225 [opt]
frame #13: 0x0000000112d36ca2 XUL`NS_ProcessPendingEvents(aThread=0x000000011288c9e0, aTimeout=10) at nsThreadUtils.cpp:434 [opt]
frame #14: 0x000000011555af5f XUL`nsBaseAppShell::NativeEventCallback(this=0x0000000124f8a5e0) at nsBaseAppShell.cpp:87 [opt]
frame #15: 0x00000001155c3438 XUL`nsAppShell::ProcessGeckoEvents(aInfo=0x0000000124f8a5e0) at nsAppShell.mm:440 [opt]
frame #16: 0x00000001095daa31 CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 17
frame #17: 0x00000001095bb92d CoreFoundation`__CFRunLoopDoSources0 + 557
frame #18: 0x00000001095bae26 CoreFoundation`__CFRunLoopRun + 934
frame #19: 0x00000001095ba824 CoreFoundation`CFRunLoopRunSpecific + 420
frame #20: 0x000000010cfb1ebc HIToolbox`RunCurrentEventLoopInMode + 240
frame #21: 0x000000010cfb1cf1 HIToolbox`ReceiveNextEventCommon + 432
frame #22: 0x000000010cfb1b26 HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter + 71
frame #23: 0x0000000109cb8a04 AppKit`_DPSNextEvent + 1120
frame #24: 0x000000010a4347ee AppKit`-[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 2796
frame #25: 0x00000001155c295b XUL`::-[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:](self=0x00000001128b49d0, _cmd=<unavailable>, mask=18446744073709551615, expiration=4001-01-01 00:00:00 UTC, mode="kCFRunLoopDefaultMode", flag=YES) at nsAppShell.mm:169 [opt]
frame #26: 0x0000000109cad38b AppKit`-[NSApplication run] + 926
frame #27: 0x00000001155c3b49 XUL`nsAppShell::Run(this=0x0000000124f8a5e0) at nsAppShell.mm:703 [opt]
frame #28: 0x00000001168c693e XUL`nsAppStartup::Run(this=0x0000000124ffbba0) at nsAppStartup.cpp:276 [opt]
frame #29: 0x00000001169d7e6a XUL`XREMain::XRE_mainRun(this=0x00007fff56ad0d80) at nsAppRunner.cpp:4586 [opt]
frame #30: 0x00000001169d88e0 XUL`XREMain::XRE_main(this=0x00007fff56ad0d80, argc=<unavailable>, argv=<unavailable>, aConfig=<unavailable>) at nsAppRunner.cpp:4721 [opt]
frame #31: 0x00000001169d8db8 XUL`XRE_main(argc=<unavailable>, argv=<unavailable>, aConfig=<unavailable>) at nsAppRunner.cpp:4802 [opt]
frame #32: 0x000000010912edd8 firefox`main [inlined] do_main(argc=<unavailable>, argv=0x00007fff56ad1340, envp=0x00007fff56ad1358) at nsBrowserApp.cpp:218 [opt]
frame #33: 0x000000010912eb4c firefox`main(argc=<unavailable>, argv=<unavailable>, envp=0x00007fff56ad1358) at nsBrowserApp.cpp:300 [opt]
frame #34: 0x000000010f7b9235 libdyld.dylib`start + 1
The worker is stored in a local variable in the Promise constructor function in getSymbolTable. Do I need to do anything else to keep the worker alive?
|
||
Comment 1•6 years ago
|
||
For now you need to hold a strong reference to the Worker binding outside the "message" listener because the worker doesn't realize it's busy and capable of generating a message. (This is a bug, namely bug 1592227.)
If you have cycles to help address the underlying problem, I'd be very happy to give you a brain dump on the situation.
|
|
||
Comment 2•6 years ago
|
||
A pernosco trace would also be valuable/a helpful shortcut if you can get one.
|
Reporter | |
Comment 3•6 years ago
|
||
Interesting, thanks!
Any ideas where exactly I could store that reference here? Maybe like this?
let worker;
let promise = new Promise((resolve, reject) => {
worker = ... // rest of the code as before
});
promise.workerReferenceBug1592227 = worker;
return promise;
(In reply to Andrew Sutherland [:asuth] (he/him) from comment #2)
A pernosco trace would also be valuable/a helpful shortcut if you can get one.
Good point. I haven't reproduced this on Linux yet, but I should be able to.
|
|
||
Comment 4•6 years ago
|
||
That would work if something is retaining a strong reference to the promise rather than effectively calling promise.then() and letting the original promise and its expando fall away. I don't know enough about how our JS engine's await works under the hood to guess.
Given how reliably this reproduces, it might be easiest to just try that, and if it doesn't work, do something like https://bugzilla.mozilla.org/show_bug.cgi?id=1592227#c1 does where you have a global where you stash the Worker in a Set and it should remove itself when it's done. (One might also add an "error" listener and clear in that event too.)
Description
•