Verify if we can have a different order inside AppShutdown:.AdvanceShutdownPhaseInternal
Categories
(Core :: XPCOM, task)
Tracking
()
| Tracking | Status | |
|---|---|---|
| firefox110 | --- | ? |
People
(Reporter: jstutte, Assigned: jstutte)
References
Details
Attachments
(4 files, 1 obsolete file)
The historical and tested for order frees the ClearOnShutdown'ed pointers first and in case performs the fast shutdown then for all phases != XPCOMShutdownFinal.
We think it would be more logical to have the following order here:
AppShutdown::MaybeFastShutdown(aPhase);
sTerminator->AdvancePhase(aPhase);
obsService->NotifyObservers(...);
mozilla::KillClearOnShutdown(aPhase);
In practice we have currently only 3 phases for which this is relevant:
CCPostLastCycleCollectionXPCOMShutdownThreadsXPCOMShutdown
Most ClearOnShutdown'ed pointers are instead associated to phase XPCOMShutdownFinal (which has no associated observer topic), meaning that for those the order here is irrelevant. Furthermore setting toolkit.shutdown.fastShutdownStage = 2 or 3 means to skip the phase XPCOMShutdownFinal entirely.
However, we will need to verify that this change will not affect the (few) pointers meant to die with CCPostLastCycleCollection, XPCOMShutdownThreads or XPCOMShutdown.
Edit: We decided to not switch KillClearOnShutdown and NotifyObservers for now. But we want to anticipate the MaybeFastShutdown in order to skip the entire phase it is defined for.
| Assignee | ||
Updated•3 years ago
|
| Assignee | ||
Comment 1•3 years ago
|
||
This change will effectively anticipate the fast shutdown by one phase, making it more coherent with the phase it is defined to happen.
We also anticipate the notification to happen before the KillClearOnShutdown, such that we can first react before the objects go away.
Depends on D160250
Updated•3 years ago
|
| Assignee | ||
Comment 2•3 years ago
|
||
Depends on D160628
Updated•3 years ago
|
Updated•3 years ago
|
Comment 4•3 years ago
•
|
||
Backed out 3 changesets (Bug 1768581, Bug 1709184) for causing multiple failures on LateWriteChecks.cpp.
Backout link
Push with failures <--> gpu
Failure Log
Also R1 Failure Log, Also R2 Failure Log, ...
| Assignee | ||
Comment 5•3 years ago
•
|
||
OK, I should have definitely done more testing on other systems than linux.
It appears that moving MaybeFastShutdown to happen before KillClearOnShutdown not only anticipates the exit(0) in case but arms the LateWriteObserver earlier than before. And this seems to have consequences only on some systems, apparently.
It also explains why we could have 3 => XPCOMShutdown for toolkit.shutdown.lateWriteChecksStage while we had only 1 => CCPostLastCycleCollection for toolkit.shutdown.fastShutdownStage as we effectively armed the LateWriteObserver only for things happening after we notified XPCOMShutdown.
I'd propose to move toolkit.shutdown.lateWriteChecksStage to happen for XPCOMShutdownThreads for now, as we have many listeners for XPCOMShutdown and checking all of them for late writes is probably desirable but out of scope here.
Comment 7•3 years ago
•
|
||
Backed out for causing xpcshell failures
- Backout link
- Push with failures
- Failure Log
- Failure line: TEST-UNEXPECTED-FAIL | extensions/pref/autoconfig/test/unit/test_autoconfig.js | xpcshell return code: -6
SUMMARY: ThreadSanitizer: SEGV /builds/worker/checkouts/gecko/xpcom/base/nsISupportsImpl.cpp:53:12 in nsAutoOwningEventTarget
TEST-UNEXPECTED-FAIL | extensions/pref/autoconfig/test/unit/test_autoconfig_nonascii.js | xpcshell return code: -6
SUMMARY: ThreadSanitizer: SEGV /builds/worker/checkouts/gecko/xpcom/base/nsISupportsImpl.cpp:53:12 in nsAutoOwningEventTarget
TEST-UNEXPECTED-FAIL | extensions/pref/autoconfig/test/unit/test_autoconfig_no_sandbox.js | xpcshell return code: -6
SUMMARY: ThreadSanitizer: SEGV /builds/worker/checkouts/gecko/xpcom/base/nsISupportsImpl.cpp:53:12 in nsAutoOwningEventTarget
Can you also please take a look at this? https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&searchStr=android%2Cbrowsertime&revision=bd3bc1478107b9a72ce5dded92b7821e87a0e052&selectedTaskRun=TQNO9jTxSQ2KK0ouVXURHA.0
| Assignee | ||
Comment 8•3 years ago
•
|
||
So bug 1709184 comment 54 still applies to these tests. IIUC those tests explicitly initialize Cc["@mozilla.org/readconfig;1"].getService(Ci.nsISupports); which then gets torn down only at step nsComponentManagerImpl::gComponentManager->FreeServices();. Given that at this point we already threw away our main thread nsThread I wonder how this could ever work. AFAICS GetCurrentEventTarget will return nullptr after we shut down the main thread, making us trap into bug 1709184 comment 54. Honestly I do not know why this would have worked before the changes of this patch stack.
:kmag, is there a reason you are aware of why we wait with nsComponentManagerImpl::gComponentManager->FreeServices(); until after we shut the main thread down? I'll might want to try out what happens if I invert the order here.
| Assignee | ||
Comment 9•3 years ago
|
||
| Assignee | ||
Comment 10•3 years ago
|
||
I tried to postpone the destruction of our MT nsThread object until after XPCOM shutdown. This seems to work for the tests themselves, except that it makes us apparently leak an nsThread object in mochitests at shutdown (while we actually don't). Still this would seem to me to be the least invasive thing to do as we do not need to change the order of anything else? It feels kind of correct to keep our nsThread instance around while we are still processing events on the thread?
What step in shutdown makes us stop writing to runtests_leaks.log ? It is also kind of puzzling that this seems not to be a problem in child processes, only the parent process seems to suffer from this.
| Assignee | ||
Comment 11•3 years ago
•
|
||
(In reply to Jens Stutte [:jstutte] from comment #10)
I tried to postpone the destruction of our MT
nsThreadobject until after XPCOM shutdown. This seems to work for the tests themselves, except that it makes us apparently leak an nsThread object in mochitests at shutdown (while we actually don't). Still this would seem to me to be the least invasive thing to do as we do not need to change the order of anything else? It feels kind of correct to keep our nsThread instance around while we are still processing events on the thread?What step in shutdown makes us stop writing to
runtests_leaks.log? It is also kind of puzzling that this seems not to be a problem in child processes, only the parent process seems to suffer from this.
Actually running mochitests locally does not show leaks. Could there be some race between the main process writing the last lines and the test harness reading the log?
Edit: AFAICS we calculate these statistics inside our same process and then just do nsTraceRefcnt::DumpStatistics.
| Assignee | ||
Comment 12•3 years ago
|
||
(In reply to Jens Stutte [:jstutte] from comment #10)
What step in shutdown makes us stop writing to
runtests_leaks.log?
IIUC this is NS_LogTerm(); at the very end of our shutdown. So I cannot really see how releasing the main thread objects slightly later can cause these leaks.
Updated•3 years ago
|
Updated•3 years ago
|
Comment 13•3 years ago
|
||
Comment 14•3 years ago
|
||
Backed out for causing high frequency Xpcshell failures at test_bug1274685_unowned_list.js.
Backout link: https://hg.mozilla.org/integration/autoland/rev/3ad1c1ea9b5b9d2060e9fccc9485808e80927e38
Failure log: https://treeherder.mozilla.org/logviewer?job_id=397498581&repo=autoland&lineNumber=4077
Comment 15•3 years ago
|
||
| Assignee | ||
Comment 16•3 years ago
|
||
(In reply to Cristian Tuns from comment #15)
Can you please also take a look at this: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&searchStr=android%2C11.0%2Csamsung%2Ca51%2Cshippable%2Caarch64%2Cbrowsertime&revision=eee37f3bfaba651c3625e9e6288fa0130e2eec1f&selectedTaskRun=PwFKQvoXS_iZod3UZzqgvA.0 ?
Are the patches from this bug really involved here? I see bug 1800263 there?
Comment 17•3 years ago
•
|
||
I backfill it, but it takes a while so my logic was: this happened before https://bugzilla.mozilla.org/show_bug.cgi?id=1768581#c7
and after relanding this, it happened again, and after both backouts this got fixed. https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&searchStr=android%2C11.0%2Csamsung%2Ca51%2Cshippable%2Caarch64&fromchange=eee37f3bfaba651c3625e9e6288fa0130e2eec1f&tochange=c5ab6ec39412dc0c7f750bc29c01edc816cbcc04&selectedTaskRun=Q1px2gXJSc-jvCjcQhp84g.0
I can investigate more if needed but I think it is caused by this bug, please let me know.
| Assignee | ||
Comment 18•3 years ago
•
|
||
(In reply to Atila Butkovits from comment #14)
Backed out for causing high frequency Xpcshell failures at test_bug1274685_unowned_list.js.
Backout link: https://hg.mozilla.org/integration/autoland/rev/3ad1c1ea9b5b9d2060e9fccc9485808e80927e38
Failure log: https://treeherder.mozilla.org/logviewer?job_id=397498581&repo=autoland&lineNumber=4077
So this test seems to have a problem, see bug 1802318. I managed to work around it, doing the extra round of processing only if it is needed. This optimization accidentally heals that test, but someone should look into it.
(In reply to Cristian Tuns from comment #17)
I backfill it, but it takes a while so my logic was: this happened before https://bugzilla.mozilla.org/show_bug.cgi?id=1768581#c7
and after relanding this, it happened again, and after both backouts this got fixed. https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&searchStr=android%2C11.0%2Csamsung%2Ca51%2Cshippable%2Caarch64&fromchange=eee37f3bfaba651c3625e9e6288fa0130e2eec1f&tochange=c5ab6ec39412dc0c7f750bc29c01edc816cbcc04&selectedTaskRun=Q1px2gXJSc-jvCjcQhp84g.0
I can investigate more if needed but I think it is caused by this bug, please let me know.
It seems indeed to reproduce on my patch stack. I am checking now with the workaround for the above test, but if that does not help I think we need to disable some of this for Android (IIUC we actually do not care about a clean shutdown there, anyways).
| Assignee | ||
Comment 19•3 years ago
|
||
The CookieService singleton observes "profile-before-change"
(ShutdownPhase::AppShutdown) to destroy the cookie storages, but uses
ClearOnShutdown in order to release itself.
If we tried to use it the first time after ShutdownPhase::AppShutdown,
InitCookieServices would instantiate a new DB connection that is never
removed until MozStorage asserts.
As a minimal invasive hack we check the shutdown phase in
InitCookieStorage and in case deviate to a CookiePrivateStorage.
As a follow up we should probably verify, up to which shutdown phase we
really want to be able to provide the CookieService as a whole.
Depends on D162497
| Assignee | ||
Comment 20•3 years ago
|
||
(In reply to Jens Stutte [:jstutte] from comment #18)
I am checking now with the workaround for the above test, but if that does not help I think we need to disable some of this for Android (IIUC we actually do not care about a clean shutdown there, anyways).
This revealed another problem, here is a push with the current patch stack. For reasons I do not know the Android YouTube tests are always pending, is there something else I need to trigger in order to unblock them?
Updated•3 years ago
|
Updated•3 years ago
|
Updated•3 years ago
|
| Assignee | ||
Comment 21•3 years ago
•
|
||
(removing kmag as I think there are no open questions left for you right now).
| Assignee | ||
Comment 22•3 years ago
|
||
(In reply to Jens Stutte [:jstutte] from comment #20)
For reasons I do not know the Android YouTube tests are always pending, is there something else I need to trigger in order to unblock them?
There seems to be just a bottleneck on treeherder for that kind of tasks.
| Assignee | ||
Comment 23•3 years ago
|
||
Depends on D163128
| Assignee | ||
Comment 24•3 years ago
|
||
Excluding Android from the extra processing solves the browsertime issue there, though it feels like a pre-existing race we just trip over permanently here.
| Assignee | ||
Comment 25•3 years ago
•
|
||
(In reply to Jens Stutte [:jstutte] from comment #21)
This push shows some very frequent intermittent for browser_ext_browserAction_context.js, see bug 1775555. Running that test locally on Windows opt failed for me frequently, too, and looking into it a bit more I noticed that the removeDirectory background task is run several times during that test, and being a background task a parent process, my changes regarding shutdown extra main thread processing might have affected its timing here. :saschanaz, :valentin, do you see something specific to investigate here?
| Assignee | ||
Comment 26•3 years ago
|
||
| Assignee | ||
Comment 27•3 years ago
|
||
(In reply to Jens Stutte [:jstutte] from comment #25)
This push shows some very frequent intermittent for
browser_ext_browserAction_context.js, see bug 1775555. Running that test locally on Windows opt failed for me frequently, too, and looking into it a bit more I noticed that theremoveDirectorybackground task is run several times during that test, and being a background task a parent process, my changes regarding shutdown extra main thread processing might have affected its timing here. :saschanaz, :valentin, do you see something specific to investigate here?
I assume :rpl found the underlying issue over there.
| Assignee | ||
Comment 28•3 years ago
•
|
||
A closer look (again) at the Android failures as Nika does not like (and is probably right in not liking it) the exception for Android. Let's start from what I can see (and what not) in the test runs:
- Failing run with my patchstack - It seems from the film that youtube asks for consent here. This is confirmed by the mitmproxy.log where I read
killed non-replay request https://consent.youtube.com/_/ConsentUi/browserinfo?.... - Successful run contains no video, and the mitmproxy.log also contains URLs with
ConsentUI. - Failing run from intermittent bug 1642205 shows none of the above artefacts and failed earlier, probably for some taskcluster internal thing.
So the failure we see here seems to be different from the existing intermittent failures elsewhere.
Going to look at both logs side by side.
| Assignee | ||
Comment 29•3 years ago
|
||
11-24 05:03:06.238 13277 25897 I Gecko : 1669266186237 Marionette DEBUG 0 -> [0,106,"Marionette:Quit",{"flags":["eForceQuit"]}]
11-24 05:03:06.241 13277 25897 I Gecko : 1669266186240 Marionette INFO Stopped listening on port 2829
11-24 05:03:06.261 13277 25897 D GeckoViewNavigation: canClose
11-24 05:03:06.272 13277 25897 D GeckoViewContent: handleEvent: DOMWindowClose
11-24 05:03:06.275 13277 25897 I Gecko : 1669266186274 Marionette TRACE Received observer notification quit-application
11-24 05:03:06.276 13277 25897 I Gecko : 1669266186276 Marionette TRACE Received observer notification quit-application
11-24 05:03:06.277 13277 25897 I Gecko : 1669266186277 Marionette DEBUG Marionette stopped listening
we see Marionette receiving eForceQuit and GeckoViewContent handling DOMWindowClose seems to end up signaling quit-application to Gecko.
In the failure case:
11-26 10:23:21.724 12670 27772 I Gecko : 1669458201724 Marionette DEBUG 0 -> [0,108,"Marionette:Quit",{"flags":["eForceQuit"]}]
11-26 10:23:21.726 12670 27772 I Gecko : 1669458201726 Marionette INFO Stopped listening on port 2829
11-26 10:23:21.746 12670 27772 D GeckoViewNavigation: canClose
11-26 10:23:21.760 12670 27772 D GeckoViewContent: handleEvent: DOMWindowClose
11-26 10:23:21.766 4603 5742 E BufferQueueProducer: [GeckoSurface#0](id:11fb00000013,api:0,p:-1,c:4603) disconnect: not connected (req=1)
11-26 10:23:21.767 27837 27872 W libEGL : EGLNativeWindowType 0x7be4b02010 disconnect failed
11-26 10:23:21.781 12670 27772 D GeckoViewNavigation: onDisable
11-26 10:23:21.782 12670 27772 D GeckoViewProcessHangMonitor: onDisable
11-26 10:23:21.782 27997 28019 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
11-26 10:23:21.782 12670 27772 D GeckoViewModule: unregisterListener
11-26 10:23:21.783 12670 27772 D GeckoViewProcessHangMonitor: onDestroy
11-26 10:23:21.784 12670 27772 D GeckoViewProgress: onDisable
11-26 10:23:21.784 12670 27772 D GeckoViewModule: unregisterListener
11-26 10:23:21.785 12670 27772 D GeckoViewSelectionAction: onDisable
11-26 10:23:21.786 12670 27772 D GeckoViewModule: unregisterListener
11-26 10:23:21.787 27997 28019 D GeckoViewClipboardPermissionChild[C]: handleEvent: deactivate
11-26 10:23:21.787 12670 27772 D GeckoViewModule: unregisterListener
11-26 10:23:21.793 12670 27772 D GeckoViewSessionStore: observe browsing-context-discarded
11-26 10:23:21.793 12670 27772 D GeckoViewSessionStore: observe browsing-context-discarded
11-26 10:23:21.794 12670 27772 D GeckoViewSessionStore: observe browsing-context-discarded
11-26 10:23:21.798 12670 27772 D GeckoViewSessionStore: observe browsing-context-discarded
11-26 10:23:21.804 27997 28019 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
11-26 10:23:21.805 27997 28019 D GeckoViewClipboardPermissionChild[C]: handleEvent: pagehide
11-26 10:23:21.806 27997 28019 D GeckoViewAutoFill[C]: handleEvent: pagehide
11-26 10:23:21.831 12670 27772 D GeckoViewClipboardPermissionParent: receiveMessage: DispatcherMessage
11-26 10:23:21.832 12670 27772 D GeckoViewActorParent: receiveMessage window destroyed DispatcherMessage GeckoView:DismissClipboardPermissionRequest
11-26 10:23:21.835 12670 27772 D GeckoViewClipboardPermissionParent: receiveMessage: DispatcherMessage
11-26 10:23:21.836 12670 27772 D GeckoViewActorParent: receiveMessage window destroyed DispatcherMessage GeckoView:DismissClipboardPermissionRequest
11-26 10:23:21.837 12670 27772 D GeckoViewAutoFill: receiveMessage Clear
11-26 10:23:21.857 12670 27772 W google-breakpad: ExceptionHandler::GenerateDump cloned child
11-26 10:23:21.857 12670 27772 W google-breakpad: 28250
11-26 10:23:21.857 12670 27772 W google-breakpad:
11-26 10:23:21.857 12670 27772 W google-breakpad: ExceptionHandler::SendContinueSignalToChild sent continue signal to child
11-26 10:23:21.857 28250 27772 W google-breakpad: ExceptionHandler::WaitForContinueSignal waiting for continue signal...
11-26 10:23:22.140 4307 4307 I io_stats: !@ 8,0 r 329501 5921520 w 19752 550584 d 11854 200288 f 12256 15365 iot 70908 65942 th 102400 0 0 pt 0 inp 0 0 595.006
11-26 10:23:22.831 4458 4458 E audit : type=1701 audit(1669458202.827:803): auid=4294967295 uid=10268 gid=10268 ses=4294967295 subj=u:r:untrusted_app:s0:c12,c257,c512,c768 pid=12670 comm="Gecko" exe="/system/bin/app_process64" sig=11 res=1
11-26 10:23:22.921 4927 5084 W InputDispatcher: channel 'a16ca3f org.mozilla.geckoview_example/org.mozilla.geckoview_example.GeckoViewActivity (server)' ~ Consumer closed input channel or an error occurred. events=0x9, fd=700
11-26 10:23:22.921 4927 5084 E InputDispatcher: channel 'a16ca3f org.mozilla.geckoview_example/org.mozilla.geckoview_example.GeckoViewActivity (server)' ~ Channel is unrecoverably broken and will be disposed!
11-26 10:23:22.923 27997 28021 I Gecko : Exiting due to channel error.
11-26 10:23:22.923 27788 27907 I Gecko : Exiting due to channel error.
11-26 10:23:22.929 4927 7322 D InputTransport: Input channel destroyed: 'ClientS', fd=417
the quit-application notification seems to never arrive. This looks relevant to what we do here.
Updated•3 years ago
|
| Assignee | ||
Comment 30•3 years ago
|
||
OK, I think I understand know what is happening with marionette here. Basically Marionette wraps nsAppStartup::Quit with a synchronous function that expects to return immediately. If instead we do Ns_ProcessPendingEvents after we did NotifyObservers for AppShutdownConfirmed, we will process all the shutdown sequence inside that wrapped call and Marionette will never receive an answer, as the process dies before. This seems to not really be a problem for normal running mode, though it definitely feels better to exclude AppShutdownConfirmed entirely from any extra processing, also to avoid eventually being called on top of a nested event loop.
Updated•3 years ago
|
Updated•3 years ago
|
Comment 31•3 years ago
|
||
Comment 32•3 years ago
|
||
| bugherder | ||
| Assignee | ||
Updated•3 years ago
|
Updated•3 years ago
|
Description
•