Closed Bug 1768581 Opened 4 years ago Closed 3 years ago

Verify if we can have a different order inside AppShutdown:.AdvanceShutdownPhaseInternal

Categories

(Core :: XPCOM, task)

task

Tracking

()

RESOLVED FIXED
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:

  1. CCPostLastCycleCollection
  2. XPCOMShutdownThreads
  3. XPCOMShutdown

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.

See Also: → 1766572
See Also: → 1797688
Keywords: leave-open

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

Assignee: nobody → jstutte
Status: NEW → ASSIGNED
Attachment #9300751 - Attachment description: Bug 1768581 - Part 12: Swap the order of NotifyObserver and KillClearOnShutdown inside AdvanceShutdownPhase and add extra NS_ProcessPendingEvents for the main thread. r?#xpcom-reviewers → Bug 1768581 - Part 12: Swap the order of MaybeFastShutdown and KillClearOnShutdown inside AdvanceShutdownPhase and add extra NS_ProcessPendingEvents for the main thread. r?#xpcom-reviewers
Attachment #9300754 - Attachment is obsolete: true
Pushed by jstutte@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/c49173f72e0d Part 12: Swap the order of MaybeFastShutdown and KillClearOnShutdown inside AdvanceShutdownPhase and add extra NS_ProcessPendingEvents for the main thread. r=xpcom-reviewers,nika

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, ...

Also X4 almost perma --> Failure Log

Flags: needinfo?(jstutte)

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.

Flags: needinfo?(jstutte)
Pushed by jstutte@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/bd3bc1478107 Part 12: Swap the order of MaybeFastShutdown and KillClearOnShutdown inside AdvanceShutdownPhase and add extra NS_ProcessPendingEvents for the main thread. r=xpcom-reviewers,nika

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

Flags: needinfo?(jstutte)

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.

Flags: needinfo?(jstutte) → needinfo?(kmaglione+bmo)

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.

(In reply to Jens Stutte [:jstutte] from comment #10)

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.

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.

(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.

Attachment #9304336 - Attachment description: WIP: Bug 1768581 - Postpone main nsThread destruction after full XPCOM shutdown. → WIP: Bug 1768581 - Part 13: Postpone main nsThread destruction after full XPCOM shutdown.
Attachment #9304336 - Attachment description: WIP: Bug 1768581 - Part 13: Postpone main nsThread destruction after full XPCOM shutdown. → Bug 1768581 - Part 13: Postpone main nsThread destruction after full XPCOM shutdown. r?#xpcom-reviewers
Pushed by jstutte@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/1f111f5b8baf Part 12: Swap the order of MaybeFastShutdown and KillClearOnShutdown inside AdvanceShutdownPhase and add extra NS_ProcessPendingEvents for the main thread. r=xpcom-reviewers,nika https://hg.mozilla.org/integration/autoland/rev/6bae0f16eae9 Part 13: Postpone main nsThread destruction after full XPCOM shutdown. r=xpcom-reviewers,nika
Flags: needinfo?(jstutte) → needinfo?(ctuns)

(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

Push with failures: https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&revision=6bae0f16eae92d5313470ff784c1e3eeca78e80a&selectedTaskRun=H3uhjloVQtuen4U0QVS1PQ.0

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).

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

(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?

Flags: needinfo?(ctuns)
Depends on: 1657551
Depends on: 1802318
Attachment #9300751 - Attachment description: Bug 1768581 - Part 12: Swap the order of MaybeFastShutdown and KillClearOnShutdown inside AdvanceShutdownPhase and add extra NS_ProcessPendingEvents for the main thread. r?#xpcom-reviewers → Bug 1768581 - Part 3 Swap the order of MaybeFastShutdown and KillClearOnShutdown inside AdvanceShutdownPhase and add extra NS_ProcessPendingEvents for the main thread. r?#xpcom-reviewers
Attachment #9304336 - Attachment description: Bug 1768581 - Part 13: Postpone main nsThread destruction after full XPCOM shutdown. r?#xpcom-reviewers → Bug 1768581 - Part 4: Postpone main nsThread destruction after full XPCOM shutdown. r?#xpcom-reviewers
Attachment #9305207 - Attachment description: Bug 1768581 - Part 14: Avoid late initialization of permanent cookie storage. r?#necko-reviewers → Bug 1768581 - Part 5: Avoid late initialization of permanent cookie storage. r?#necko-reviewers

New try push.

(removing kmag as I think there are no open questions left for you right now).

Flags: needinfo?(kmaglione+bmo)

(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.

Flags: needinfo?(ctuns)

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.

See Also: → 1642205

(In reply to Jens Stutte [:jstutte] from comment #21)

New try push.

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?

Flags: needinfo?(valentin.gosu)
Flags: needinfo?(krosylight)
See Also: → 1775555

(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 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?

I assume :rpl found the underlying issue over there.

Flags: needinfo?(valentin.gosu)
Flags: needinfo?(krosylight)

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:

  1. 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?....
  2. Successful run contains no video, and the mitmproxy.log also contains URLs with ConsentUI.
  3. 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.

In a successful run

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.

Attachment #9305486 - Attachment description: Bug 1768581 - Part 8: Limit extra MT processing to non-Android processes and have an extra round only if KillClearOnShutdown deleted something. r?#xpcom-reviewers → Bug 1768581 - Part 8: Exclude AppShutdownConfirmed from any Ns_ProcessPendingEvents and have an extra round of MT processing only if KillClearOnShutdown deleted something. r?#xpcom-reviewers

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.

Attachment #9305486 - Attachment description: Bug 1768581 - Part 8: Exclude AppShutdownConfirmed from any Ns_ProcessPendingEvents and have an extra round of MT processing only if KillClearOnShutdown deleted something. r?#xpcom-reviewers → Bug 1768581 - Part 8: Exclude AppShutdownConfirmed from any Ns_ProcessPendingEvents and have an extra round of MT processing after KillClearOnShutdown. r?#xpcom-reviewers
Attachment #9305486 - Attachment description: Bug 1768581 - Part 8: Exclude AppShutdownConfirmed from any Ns_ProcessPendingEvents and have an extra round of MT processing after KillClearOnShutdown. r?#xpcom-reviewers → Bug 1768581 - Part 8: Exclude AppShutdownConfirmed from any Ns_ProcessPendingEvents. r?#xpcom-reviewers
Pushed by jstutte@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/9dd8e171ceec Part 3 Swap the order of MaybeFastShutdown and KillClearOnShutdown inside AdvanceShutdownPhase and add extra NS_ProcessPendingEvents for the main thread. r=xpcom-reviewers,nika https://hg.mozilla.org/integration/autoland/rev/3ea9d762d4b3 Part 4: Postpone main nsThread destruction after full XPCOM shutdown. r=xpcom-reviewers,nika https://hg.mozilla.org/integration/autoland/rev/b9c4d8c3dab6 Part 5: Avoid late initialization of permanent cookie storage. r=necko-reviewers,valentin https://hg.mozilla.org/integration/autoland/rev/2d47b42cec13 Part 8: Exclude AppShutdownConfirmed from any Ns_ProcessPendingEvents. r=xpcom-reviewers,nika
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Keywords: leave-open
Resolution: --- → FIXED
Depends on: 2062119
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: