1590114 - DeferredTask's finalize method may wait unnecessarily long due to idle dispatch

Status: RESOLVED FIXED

(Toolkit :: Async Tooling, defect, P1)

Description

[Rob Wu [:robwu]]

While developing and running a new test locally, I consistently observed that it took a noticeable amount of time before the test shut down. I managed to measure the immediate reason for this. Apparently, DeferredTask waits for at least 5-8 seconds during a call to finalize (measured and pinpointed to the delay between scheduling and running PromiseUtils.idleDispatch in DeferredTask.jsm) when the test has finished.

The culprit for my observation was that the XPIDatabase.jsm uses an armed DeferredTask, and XPIDatabase.shutdown awaits the finalization of that task. This in its turn blocks XPIProvider.shutdown, which blocks shutdown via AddonManager.jsm, aka AsyncShutdown + "AddonManager: Waiting for providers to shut down".

I have observed a delay of a few seconds, but in theory this could be even longer. Anything that blocks shutdown should not sit idle, but run ASAP when shutdown commences.

There are multiple occurrences of DeferredTask + arm + finalize that block AsyncShutdown, and this bug might have contributed to part of those known AsyncShutdown timeout crashes:

• bug 1542045 - use of finalize in AsyncShutdown "Flush WebExtension StartupCache"
• bug 1315306 - use of finalize in shutdown , and some crash reports that match the condition.
• bug 1453520 - use of finalize (anything that uses JSONFile may be affected)
• bug 1504628 - the example above that lead to this bug report

Comment 1

[Rob Wu [:robwu]]

The current logic was introduced in bug 1391707.

There was clearly an intent to minimize the impact on finalize, according to the comment at https://searchfox.org/mozilla-central/rev/d7537a9cd2974efa45141d974e5fc7c727f1a78f/toolkit/modules/DeferredTask.jsm#312-313

      // If we're being finalized, execute the task immediately, so we don't
      // risk blocking async shutdown longer than necessary.

However, the logic did not account for potentially long delays from previously scheduled tasks that block shutdown at https://searchfox.org/mozilla-central/rev/d7537a9cd2974efa45141d974e5fc7c727f1a78f/toolkit/modules/DeferredTask.jsm#258-261

I'm going to attach a patch that addresses this issue.

Comment 2

[Rob Wu [:robwu]]

Attachment: Bug 1590114 - Move idle dispatch from task to timer in DeferredTask.jsm

DeferredTask's finalize() awaits the completion of any (previously)
scheduled tasks before returning. To minimize the time spent in
finalize(), the idle dispatch timer should not be a part of the task
execution, but part of the (cancelable) timer.

Comment 3

[Rob Wu [:robwu]]

Attachment: Bug 1590114 - Cleanup references to generators in DeferredTask

Task.jsm and function* tasks do not exist any more.

Depends on D49936

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/df2ae0b114e0
Move idle dispatch from task to timer in DeferredTask.jsm r=florian
https://hg.mozilla.org/integration/autoland/rev/ceca727602a1
Cleanup references to generators in DeferredTask r=florian

Comment 5

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/df2ae0b114e0
https://hg.mozilla.org/mozilla-central/rev/ceca727602a1

Comment 6

[Ryan VanderMeulen [:RyanVM]]

I'm a bit on the fence about whether we should consider uplifting this to Beta or not. Is there any particular signature we can look at to determine if this helped with the AsyncShutdown crashes?

Comment 7

[Rob Wu [:robwu]]

I looked up signatures of callers of DeferredTask that uses finalize in a blocker. The links are below. If anything, this bug is only a part of the cause, by adding just enough time to other resource-consuming tasks to exceed the AsyncShutdown deadline. Some of the crashes with higher frequency involve I/O, and it is much more likely for the crash to have been caused by slow I/O than the delay from this bug (usually, idle tasks are run within a few dozen milliseconds, but I somehow managed to consistently observe a delay of several seconds while running a relatively simple xpcshell test on a powerful Linux system).

• "DownloadAutoSaveView: writing data"
• "Flush WebExtension StartupCache"
• "TelemetryController: shutting down" (filtered by relevant condition: results)
• "JSON store: writing data"
• "Flush AddonRepository"
• "XPIProvider shutdown"
• "UpdateManager: writing update xml data"

While it is possible for some of the crashes to go away with this fix, it is probably not enough to warrant an uplift.

Comment 8

[Ryan VanderMeulen [:RyanVM]]

Thanks for the info!