Closed Bug 1164886 Opened 4 years ago Closed 4 years ago

log async phase progress

Categories

(Toolkit :: Async Tooling, defect)

37 Branch
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla41
Tracking Status
firefox41 --- fixed

People

(Reporter: oliver.henshaw, Assigned: oliver.henshaw)

Details

Attachments

(1 file, 3 obsolete files)

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)
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.
Attachment #8605883 - Attachment is obsolete: true
Attachment #8607528 - Flags: feedback?(dteller)
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?
Flags: needinfo?(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.
Flags: needinfo?(oliver.henshaw)
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 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.
Attachment #8607528 - Flags: feedback?(dteller) → feedback+
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}
Attachment #8607528 - Attachment is obsolete: true
Attachment #8610517 - Flags: review?(dteller)
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.
Attachment #8610517 - Flags: review?(dteller) → review+
Assignee: nobody → oliver.henshaw
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
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).
Attachment #8610517 - Attachment is obsolete: true
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/68e277743ff8
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla41
You need to log in before you can comment on or make changes to this bug.