1164886 - log async phase progress

Status: RESOLVED FIXED

(Toolkit :: Async Tooling, defect)

Description

[Oliver Henshaw]

Attachment: Add logging for async shutdown barriers

It would be useful to be able to log when async phases complete and when individual barriers are added/removed completed.


Here's a patch to achieve that. Note that it's tested with 37.0.1 and earlier, and I haven't yet made an attempt to rebase it for bug #1112640.

Also I'm unconditionally logging - I'm not sure whether it's best to log at some higher debug level, or hide it behind a pref (like with toolkit.osfile.log)

Comment 1

[Oliver Henshaw]

Attachment: Add logging for async shutdown barriers v2

How's this? It's a little simpler, and I think it should log the lifecycle of all async barriers. I'd still like feedback on how to control logging, though.

Comment 2

[David Teller [:Yoric] - still alive but not very active]

Logging unconditionally will add to the console noise we have, so it's probably not a good idea.
Logging conditionally – I don't know. In which circumstances do you see this being used?

Comment 3

[Oliver Henshaw]

I originally wrote it while trying to get to the bottom of bug #1044556 - trying to see whether the barrier for session store write ever got out of sync with the file writes as logged by toolkit.osfile.log

Then I found it useful again - see bug #694570 comment #23 - though here it's just logging when shutdown phases complete that I needed. I guess this is actually the most important part: if shutdown (or any other user of async barriers) is regularly cut short by a crash or disconnection, it's pretty useful to see how far through teardown it's got.

Comment 4

[David Teller [:Yoric] - still alive but not very active]

I seem to remember that the shutdown terminator already writes that stuff somewhere: https://dxr.mozilla.org/mozilla-central/source/toolkit/components/terminator/nsTerminator.cpp

Can you check if all the information you need is actually written?

Comment 5

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8607528 [details] [diff] [review]
Add logging for async shutdown barriers v2

Review of attachment 8607528 [details] [diff] [review]:
-----------------------------------------------------------------

If nsTerminator.cpp doesn't do what you expect, let's do this, but with a preference.

Comment 6

[Oliver Henshaw]

It's written but not as reliable though. Plus if the log lines are written on the main thread, it's easier to know that the ordering of the logs is the ordering of the events.

And it's the ordering of events during shutdown that it is crucial to understand. e.g. with bug #694570 the X session may go away at any time after the call to DisconnectFromSM() - so firefox may crash immediately after or it may last until it finishes quitting if some other application is slower to shutdown. A shutdown crash or problem may be intermittent but the underlying cause is there on every run.


As for it being more reliable, note that my patch logs the end of the phase. The shutdown terminator starts at the beginning of the phase and logs every second or at the beginning of the next phase. But there's no guarantee that the file will get written.

e.g.

stdout:
INFO: Finished phase profile-change-teardown
INFO: Finished phase profile-before-change
INFO: Finished phase profile-before-change2
INFO: Finished phase web-workers-shutdown

Then in 'll -rt' order,

ShutdownDuration.json
{"profile-change-teardown": 0}

sessionCheckpoints.json:
{"profile-after-change":true,"final-ui-startup":true,"sessionstore-windows-restored":true,"quit-application-granted":true,"quit-application":true,"sessionstore-final-state-write-complete":true,"profile-change-net-teardown":true,"profile-change-teardown":true,"profile-before-change":true}

NOTE: this is fully written, later shutdown phases aren't written to disk aiui.

ShutdownDuration.json.tmp:
{"profile-change-teardown": 0, "profile-before-change": 0}

Comment 7

[Oliver Henshaw]

Attachment: Add logging for async shutdown barriers v3

Comment 8

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8610517 [details] [diff] [review]
Add logging for async shutdown barriers v3

Review of attachment 8610517 [details] [diff] [review]:
-----------------------------------------------------------------

r=me with the nits below addressed.

::: toolkit/components/asyncshutdown/AsyncShutdown.jsm
@@ +207,5 @@
> +  DEBUG_LOG = Services.prefs.getBoolPref(PREF_DEBUG_LOG);
> +}, false);
> +
> +function debug(msg, error=null) {
> +  if (DEBUG_LOG)

if (...) {
  ...
}

@@ +604,4 @@
>        if (typeof name != "string") {
>          throw new TypeError("Expected a human-readable name as first argument");
>        }
> +      debug("Add blocker " + name + " for phase " + this._name);

Nit: It would be a bit nicer with backquotes.

@@ +706,4 @@
>        this._promiseToBlocker.set(promise, blocker);
>        this._conditionToPromise.set(condition, promise);
>  
> +      promise = promise.then(() => debug("Completed blocker " + name + " for phase " + this._name));

Nit: Might as well do this in the `then()` just below.

Comment 9

[Oliver Henshaw]

Attachment: Add optional logging for async shutdown barriers v4

Addressed review comments and made minor changes to tense and positioning of "Add(ing) blocker" line (i.e. after all the chances for early exit).

Comment 10

[Gian-Carlo Pascutto [:gcp]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=f6489b72d5c7

Comment 11

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/68e277743ff8

Comment 12

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/68e277743ff8