Closed Bug 1301289 Opened 3 years ago Closed 3 years ago

Sync pings submitted too late in shutdown process

Categories

(Firefox :: Sync, defect, P1)

defect

Tracking

()

RESOLVED FIXED
Firefox 51
Tracking Status
firefox50 --- fixed
firefox51 --- fixed

People

(Reporter: markh, Assigned: markh)

References

Details

Attachments

(2 files)

I noticed on shutdown an error in the console:

> 1473309697806 Sync.Telemetry    TRACE   observed xpcom-shutdown null
> JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 693: Error: Phase "TelemetryController: Waiting for pending ping activity" is finished, it is too late to register completion condition "Waiting for ping task"

The problem is that we are attempting to submit a ping on the xpcom-shutdown observer - but by this point the process has torn down so far that the ping can't be archived. about:telemetry thus never shows these pings. "quit-application" seems like a better time (that's the earliest observer when we know for sure the process is tearing down.

I also noticed that we always attempt to submit a ping, even when we didn't see any Syncs - this *should* be unlikely (given our module is only initialized as Sync itself does) but it seems worthwhile checking this.
Comment on attachment 8789210 [details]
Bug 1301289 - send accumulated sync pings earlier in the shutdown process.

https://reviewboard.mozilla.org/r/77504/#review75760

::: services/sync/modules/telemetry.js:341
(Diff revision 1)
>    }
>  
>    finish(reason) {
>      // Note that we might be in the middle of a sync right now, and so we don't
>      // want to touch this.current.
> +    if (this.payloads.length) {

oops - submit() checks this, so this additional block isn't needed.
Assignee: nobody → markh
Priority: -- → P1
Summary: Sync pings submitted to late in shutdown process, and possibly with an empty payload. → Sync pings submitted too late in shutdown process
(In reply to Mark Hammond [:markh] from comment #0)
> I noticed on shutdown an error in the console:
> 
> > 1473309697806 Sync.Telemetry    TRACE   observed xpcom-shutdown null
> > JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 693: Error: Phase "TelemetryController: Waiting for pending ping activity" is finished, it is too late to register completion condition "Waiting for ping task"

We should catch this bug with a clearer error message, i will file a bug on this.
 
> The problem is that we are attempting to submit a ping on the xpcom-shutdown
> observer - but by this point the process has torn down so far that the ping
> can't be archived. about:telemetry thus never shows these pings.
> "quit-application" seems like a better time (that's the earliest observer
> when we know for sure the process is tearing down.

"profile-before-change" is also safe. If you are using AsyncShutdown, the `sendTelemetry` phase works too:
http://gecko.readthedocs.io/en/latest/toolkit/modules/toolkit_modules/AsyncShutdown.html#list-of-phases
(In reply to Georg Fritzsche [:gfritzsche] from comment #4)
> "profile-before-change" is also safe.

Thanks - I'll upload a new patch that uses that - the later we do it, the less chance we have of recording an aborted sync due to shutdown.

> If you are using AsyncShutdown

We aren't :(
Comment on attachment 8789210 [details]
Bug 1301289 - send accumulated sync pings earlier in the shutdown process.

https://reviewboard.mozilla.org/r/77504/#review75888

Ack! I should have checked this more thoroughly when working on the batching patch. Anyway, this looks fine modulo the typo.

::: services/sync/modules/telemetry.js:364
(Diff revision 3)
>  
>    submit(record) {
>      // We still call submit() with possibly illegal payloads so that tests can
>      // know that the ping was built. We don't end up submitting them, however.
>      if (record.syncs.length) {
> +      log.trace(`submitting ${record.syncs.length} sync record(s) to telemtry`);

nit: telemtry should be telemetry
Attachment #8789210 - Flags: review?(tchiovoloni) → review+
Pushed by mhammond@skippinet.com.au:
https://hg.mozilla.org/integration/autoland/rev/09e3f293166a
send accumulated sync pings earlier in the shutdown process. r=tcsc
Thanks - error was introduced in the final version of the patch and I didn't re-run the tests. Usual story :( Pushed with a test fix.
Flags: needinfo?(markh)
Pushed by mhammond@skippinet.com.au:
https://hg.mozilla.org/integration/autoland/rev/1a47959fb817
send accumulated sync pings earlier in the shutdown process. r=tcsc
https://hg.mozilla.org/mozilla-central/rev/1a47959fb817
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 51
Comment on attachment 8789210 [details]
Bug 1301289 - send accumulated sync pings earlier in the shutdown process.

Approval Request Comment
[Feature/regressing bug #]: bug 1295058
[User impact if declined]: Sync pings not sent at shutdown.
[Describe test coverage new/current, TreeHerder]: Tests pass, been on 51 for some time.
[Risks and why]: Fairly low risk - limited to sync
[String/UUID change made/needed]: None

Note bug 1295058 will need to be applied before this.
Attachment #8789210 - Flags: approval-mozilla-beta?
Waiting for a reply on this one https://bugzilla.mozilla.org/show_bug.cgi?id=1295058#c35 before deciding whether to uplift both these fixes.
Comment on attachment 8789210 [details]
Bug 1301289 - send accumulated sync pings earlier in the shutdown process.

Telemetry team has verified that this fix reduced the load on the server in Nightly51, Beta50+
Attachment #8789210 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Needs rebasing for Beta.
Flags: needinfo?(markh)
Here's a version rebased against beta.
Flags: needinfo?(markh)
Attachment #8794023 - Flags: review+
You need to log in before you can comment on or make changes to this bug.