TelemetrySession scheduler timeout does not fire right after sleep

RESOLVED FIXED in Firefox 49

Status

()

defect
P1
normal
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: gfritzsche, Assigned: gfritzsche)

Tracking

Trunk
mozilla49
Points:
3
Dependency tree / graph

Firefox Tracking Flags

(firefox48 affected, firefox49 fixed)

Details

(Whiteboard: [measurement:client])

Attachments

(2 attachments)

We expected our scheduler timeouts [0] to fire "soon" after sleep, so that e.g. when users put the computer to sleep over night, we can trigger daily pings right after the wakeup.
However, timeouts are still delayed after wakeup for as long as they would have been before sleep.
That means we could record up to 1 hour (the idle tick timer interval) into the new day.

We should either switch to a scheduling mechanism that fires soon after wakeup or - if we can - explicitly trigger scheduler ticks after wakeup.

https://dxr.mozilla.org/mozilla-central/rev/17a0ded9bb99c05c25729c306b91771483109067/toolkit/components/telemetry/TelemetrySession.jsm#173
Priority: P3 → P1
Points: --- → 3
Assignee: nobody → alessio.placitelli
I investigated the issue on Windows and it looks like timers are taking sleep/wake events in account: if a timer expires when the computer is asleep, it fires its callback as soon as it wakes up.

The sleep/wake events are correctly handled in the timers' manager [1], which ends up calling nsTimerImpl::Fire() by dispatching a |nsTimerEvent| if the timer is overdue.

I tested this behaviour with scratchpad by:

- Printing Date.now().
- Starting a timer with setTimeout [3] with a 5 minutes timeout and printing Date.now() in the callback.
- Putting my laptop to sleep.
- Waiting 10 minutes and then waking the laptop.
- The callback immediately fires and prints the current timestamp. The difference between the two timestamps matches with the sleep time.

This seems to be a Linux/Mac only issue. I think this is expected to behave as described in comment 0 on Linux (see bug 758848), but I have no idea why that doesn't work on Mac.

[1] - https://dxr.mozilla.org/mozilla-central/rev/fc15477ce628599519cb0055f52cc195d640dc94/xpcom/threads/TimerThread.cpp#795
[2] - https://dxr.mozilla.org/mozilla-central/rev/fc15477ce628599519cb0055f52cc195d640dc94/xpcom/threads/nsTimerImpl.cpp#461
[3] - https://dxr.mozilla.org/mozilla-central/rev/fc15477ce628599519cb0055f52cc195d640dc94/toolkit/modules/Timer.jsm#24
Assignee: alessio.placitelli → nobody
Assignee: nobody → gfritzsche
On Mac we get the "wake_notification" correctly:
https://dxr.mozilla.org/mozilla-central/rev/fc15477ce628599519cb0055f52cc195d640dc94/xpcom/threads/TimerThread.cpp#793

... but when we get to the timeout check after sleep here:
https://dxr.mozilla.org/mozilla-central/rev/fc15477ce628599519cb0055f52cc195d640dc94/xpcom/threads/TimerThread.cpp#462,468

... we hit bug 1204823.
The clock values returned from TimeStamp::Now() do increase during sleep on Windows, but they don't on Mac.
Consequently, we fire the timeouts after the delay passed in absolute time on Windows, but on Mac only after the delay passed in "awake"/"not suspended" time.

For now we can address this by having TelemetrySession listen to the "wake_notification" and triggering a scheduler tick from it.
This still leaves Linux (which apparently doesn't have the "wake_notification" per bug 758848), but it's at least an improvement.
Move TelemetryScheduler.shutdown() next to init() to make init/shutdown comparisons easier to read.
Attachment #8746066 - Flags: review?(alessio.placitelli)
This makes us trigger a scheduler tick when we get the wake notification. If we passed midnight, this will trigger a daily ping and thus a new subsession.
Attachment #8746071 - Flags: review?(alessio.placitelli)
Attachment #8746066 - Flags: review?(alessio.placitelli) → review+
Comment on attachment 8746071 [details] [diff] [review]
Trigger Telemetry scheduler tick after waking up from sleep

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

This looks good, but keep in mind that it might need to be reworked a bit once bug 1145188 lands.
Attachment #8746071 - Flags: review?(alessio.placitelli) → review+
https://hg.mozilla.org/mozilla-central/rev/b26e6ca414e1
https://hg.mozilla.org/mozilla-central/rev/1deceec2c122
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla49
You need to log in before you can comment on or make changes to this bug.