844331 - Support recording of Telemetry at shutdown

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[Vladan Djeric (:vladan)]

Telemetry writes out session data to a file at a very early stage of shutdown:

http://mxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/TelemetryPing.js#1083

However, Telemetry users such as FHR and Necko try to record Telemetry for shutdown operations that happen during profile-before-change:

HEALTHREPORT_SHUTDOWN_DELAY_MS
CACHE_SERVICE_LOCK_WAIT_MAINTHREAD_NSCACHESERVICE_ONPROFILESHUTDOWN
NETWORK_DISK_CACHE_DELETEDIR_SHUTDOWN

As a result, most of this data is lost and we only receive a handful of reports during weird race conditions (e.g. races between idle-daily & shutdown).

We should either move the writing of the session file to a later point in the shutdown process (e.g. as the last operation during profiler-before-change) or tell devs not to record Telemetry at shutdown.

Comment 1

[Nathan Froyd [:froydnj]]

Attachment: part 1 - rename bits with |getCurrentSessionPayload| to |getSessionPayload|

I am indifferent about this one, but the name was going to get a little
unwieldy with future commits, so...can drop it on the floor if you like.

Comment 2

[Nathan Froyd [:froydnj]]

Attachment: part 2 - move getSimpleMeasurements to live in TelemetryPing

getSimpleMeasurements should really live in TelemetryPing anyway, and moving
it, along with the consolidation of the io counters and whatnot, makes it
easier to split the construction of the ping later on.

Comment 3

[Nathan Froyd [:froydnj]]

Attachment: part 3 - split out payload/payload+slug construction to separate functions

We'll need these split out functions later.  The idea is to gather simpleMeasurements
and metadata at quit-application-granted and then gather all the histogram info
at xpcom-will-shutdown.

Comment 4

[Nathan Froyd [:froydnj]]

Attachment: part 4 - cache the profile directory in TelemetryPing

We need to get at the profile directory at xpcom-will-shutdown, but we no
longer have an active profile at that point (profile-before-change has
already run).  It seemed simplest to simply cache the profile directory
in profile-after-change and use that.  This needs changes to test code
for the xpcshell tests, which don't send the appropriate notifications.

Comment 5

[Nathan Froyd [:froydnj]]

Attachment: part 5 - move saved-session writing to xpcom-will-shutdown to catch cache and FHR activity

Here's the interesting part of the patch.

Comment 6

[(dormant account)]

Comment on attachment 719616 [details] [diff] [review]
part 3 - split out payload/payload+slug construction to separate functions

this seems reasonable. I'll trust you that this works.

Comment 7

[(dormant account)]

Comment on attachment 719617 [details] [diff] [review]
part 4 - cache the profile directory in TelemetryPing

       this.setup();
+      this.cacheProfileDirectory();

r+, but this feels like it should be done in setup(). No strong opinion here.

Comment 8

[(dormant account)]

Comment on attachment 719618 [details] [diff] [review]
part 5 - move saved-session writing to xpcom-will-shutdown to catch cache and FHR activity

Thanks for nicely-split patches.

Comment 9

[(dormant account)]

This needs a test. I'm ok with this landing without a test + doing test in a followup.

Comment 10

[Nathan Froyd [:froydnj]]

(In reply to Taras Glek (:taras) from comment #9)
> This needs a test. I'm ok with this landing without a test + doing test in a
> followup.

Do you have good ideas about how to test this?  xpcshell doesn't really do notifications, and we can't really test shutdown in, say, browser-chrome.  I guess we could try faking the notifications in xpcshell and hoping they don't crash...?  Or test-only notifications that execute the same codepaths?

It's also worth pointing out two things:

1) I forgot to add TelemetryPing of an observer of xpcom-will-shutdown.  Will fix.
2) On Windows--at least--I don't think we ever get xpcom-will-shutdown.  At least on Windows, it looks like we do a shorter shutdown sequence:

http://mxr.mozilla.org/mozilla-central/source/widget/windows/nsWindow.cpp#4544

Looks like we should be smarter about monitoring profile-before-change, perhaps?  Though it looks like FHR already looks at profile-before-change:

http://dxr.mozilla.org/mozilla-central/services/healthreport/healthreporter.jsm#l216

and records telemetry during it:

http://dxr.mozilla.org/mozilla-central/services/healthreport/healthreporter.jsm#l333

so it may be a race to see whether we can get information from FHR anyway...

Comment 11

[Nathan Froyd [:froydnj]]

(In reply to Nathan Froyd (:froydnj) from comment #10)
> (In reply to Taras Glek (:taras) from comment #9)
> > This needs a test. I'm ok with this landing without a test + doing test in a
> > followup.
> 
> Do you have good ideas about how to test this?  xpcshell doesn't really do
> notifications, and we can't really test shutdown in, say, browser-chrome.  I
> guess we could try faking the notifications in xpcshell and hoping they
> don't crash...?  Or test-only notifications that execute the same codepaths?

I see cookie tests just blithely sending profile-before-change notifications, so maybe we can get away with doing that too.

From browsing around, it looks like everybody else is saving stuff at profile-before-change.  Maybe we should be saving then too?

Comment 12

[Vladan Djeric (:vladan)]

(In reply to Nathan Froyd (:froydnj) from comment #11)
> From browsing around, it looks like everybody else is saving stuff at
> profile-before-change.  Maybe we should be saving then too?

Telemetry would have to be the *last* observer to handle the profile-before-change event since other components might record in histograms in their own handlers. I don't think there's any way to guarantee this and I'm not sure it's desirable to hack it in.

Firefox does get the "xpcom-will-shutdown" event during regular shutdowns, but the nsWindow.cpp code you linked to is the "fast shutdown" that Firefox performs when Windows tell Firefox that the user has requested OS shutdown.

What do you think of extending the "fast shutdown" sequence to also call xpcom-will-shutdown?

Comment 13

[Nathan Froyd [:froydnj]]

(In reply to Vladan Djeric (:vladan) from comment #12)
> (In reply to Nathan Froyd (:froydnj) from comment #11)
> > From browsing around, it looks like everybody else is saving stuff at
> > profile-before-change.  Maybe we should be saving then too?
> 
> Telemetry would have to be the *last* observer to handle the
> profile-before-change event since other components might record in
> histograms in their own handlers. I don't think there's any way to guarantee
> this and I'm not sure it's desirable to hack it in.

Right, that would be ugly.

> What do you think of extending the "fast shutdown" sequence to also call
> xpcom-will-shutdown?

I don't have a problem with it, the question is whether the Android and Windows folks have a problem with it.  roc, WDYT about adding xpcom-will-shutdown to the code here:

http://mxr.mozilla.org/mozilla-central/source/widget/windows/nsWindow.cpp#4557
http://mxr.mozilla.org/mozilla-central/source/widget/android/nsAppShell.cpp#379

so that we have a place to collect Telemetry data after more-or-less everybody has finished doing things in profile-before-change?

Comment 14

[Nathan Froyd [:froydnj]]

Attachment: have android and windows shutdown notify on xpcom-will-shutdown

Actually, roc, why don't you just review the patch?

Comment 15

[Nathan Froyd [:froydnj]]

Clearing needinfo.

Comment 16

[Benjamin Smedberg]

Comment on attachment 720074 [details] [diff] [review]
have android and windows shutdown notify on xpcom-will-shutdown

I don't think that this is a good name for the action being taken here. As you've described it, this is really "a notification fired right after profile-before-change". Presumably you want this notification to be fired even if we early-exit(), and xpcom-will-shutdown definitely should *not* be fired in this case.

For this case you should just create/use a profile-before-change2.

Comment 17

[Nathan Froyd [:froydnj]]

Attachment: part 5 - add profile-before-change2 notification

A semi-blind addition of notifying profile-before-change2 everywhere we
notify profile-before-change.  That dom/power bit looks *really* ugly...

Comment 18

[Nathan Froyd [:froydnj]]

Attachment: part 6 - move saved-session writing to profile-before-change2 to catch cache and FHR activity

This just moves saved-session writing to profile-before-change2.  No material
changes from the earlier part 5, so carrying over r+.

Comment 19

[Nathan Froyd [:froydnj]]

Attachment: part 5 - add profile-before-change2 notification

...and fix typoes.

Comment 20

[Benjamin Smedberg]

Please update https://wiki.mozilla.org/XPCOM_Shutdown with docs on this when it lands.

Comment 21

[Nathan Froyd [:froydnj]]

remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/62139bbc7af6
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/53c240fdf21c
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/f8e226c778e1
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/3b54f36d54a8
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/f92ce45a6b92
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/80034b418a48

Comment 22

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/62139bbc7af6
https://hg.mozilla.org/mozilla-central/rev/53c240fdf21c
https://hg.mozilla.org/mozilla-central/rev/f8e226c778e1
https://hg.mozilla.org/mozilla-central/rev/3b54f36d54a8
https://hg.mozilla.org/mozilla-central/rev/f92ce45a6b92
https://hg.mozilla.org/mozilla-central/rev/80034b418a48

Comment 23

[:Irving Reid (No longer working on Firefox)]

The xpcshell test harness does send shutdown events, if the test uses the profile:  http://mxr.mozilla.org/comm-central/source/mozilla/testing/xpcshell/head.js#909

Do we want to add profile-before-change2 there as well?

Comment 24

[Nathan Froyd [:froydnj]]

Comment on attachment 719613 [details] [diff] [review]
part 1 - rename bits with |getCurrentSessionPayload| to |getSessionPayload|

[Approval Request Comment]
Would like to upload this series to provide better measurement of things that Firefox Health Report and the network cache do.

Bug caused by (feature/regressing bug #): None
User impact if declined: No user impact.  Strictly a measurement improvement patch.
Testing completed (on m-c, etc.): On m-c for a week.
Risk to taking this patch (and alternatives if risky): Little risk.
String or UUID changes made by this patch: None.

Comment 25

[Nathan Froyd [:froydnj]]

Comment on attachment 719614 [details] [diff] [review]
part 2 - move getSimpleMeasurements to live in TelemetryPing

[Approval Request Comment]
Would like to upload this series to provide better measurement of things that Firefox Health Report and the network cache do.

Bug caused by (feature/regressing bug #): None
User impact if declined: No user impact.  Strictly a measurement improvement patch.
Testing completed (on m-c, etc.): On m-c for a week.
Risk to taking this patch (and alternatives if risky): Little risk.
String or UUID changes made by this patch: None.

Comment 26

[Nathan Froyd [:froydnj]]

Comment on attachment 719616 [details] [diff] [review]
part 3 - split out payload/payload+slug construction to separate functions

[Approval Request Comment]
Would like to upload this series to provide better measurement of things that Firefox Health Report and the network cache do.

Bug caused by (feature/regressing bug #): None
User impact if declined: No user impact.  Strictly a measurement improvement patch.
Testing completed (on m-c, etc.): On m-c for a week.
Risk to taking this patch (and alternatives if risky): Little risk.
String or UUID changes made by this patch: None.

Comment 27

[Nathan Froyd [:froydnj]]

Comment on attachment 719617 [details] [diff] [review]
part 4 - cache the profile directory in TelemetryPing

[Approval Request Comment]
Would like to upload this series to provide better measurement of things that Firefox Health Report and the network cache do.

Bug caused by (feature/regressing bug #): None
User impact if declined: No user impact.  Strictly a measurement improvement patch.
Testing completed (on m-c, etc.): On m-c for a week.
Risk to taking this patch (and alternatives if risky): Little risk.
String or UUID changes made by this patch: None.

Comment 28

[Nathan Froyd [:froydnj]]

Comment on attachment 722840 [details] [diff] [review]
part 6 - move saved-session writing to profile-before-change2 to catch cache and FHR activity

[Approval Request Comment]
Would like to upload this series to provide better measurement of things that Firefox Health Report and the network cache do.

Bug caused by (feature/regressing bug #): None
User impact if declined: No user impact.  Strictly a measurement improvement patch.
Testing completed (on m-c, etc.): On m-c for a week.
Risk to taking this patch (and alternatives if risky): Little risk.
String or UUID changes made by this patch: None.patch:

Comment 29

[Nathan Froyd [:froydnj]]

Comment on attachment 722873 [details] [diff] [review]
part 5 - add profile-before-change2 notification

[Approval Request Comment]
Would like to upload this series to provide better measurement of things that Firefox Health Report and the network cache do.

Bug caused by (feature/regressing bug #): None
User impact if declined: No user impact.  Strictly a measurement improvement patch.
Testing completed (on m-c, etc.): On m-c for a week.
Risk to taking this patch (and alternatives if risky): Little risk.
String or UUID changes made by this patch: None.

Comment 30

[bhavana bajaj [:bajaj]]

(In reply to Nathan Froyd (:froydnj) from comment #29)
> Comment on attachment 722873 [details] [diff] [review]
> part 5 - add profile-before-change2 notification
> 
> [Approval Request Comment]
> Would like to upload this series to provide better measurement of things
> that Firefox Health Report and the network cache do.
> 
> Bug caused by (feature/regressing bug #): None
> User impact if declined: No user impact.  Strictly a measurement improvement
> patch.
> Testing completed (on m-c, etc.): On m-c for a week.
> Risk to taking this patch (and alternatives if risky): Little risk.

Can you please expand a bit more on the risk here, what could be the worst thing that may happen ? 
Considering this is a last week of aurora and this seems a huge uplift right before the merge, are we worried about stability ?Also is this strictly being uplifted to help with FHR and how badly do we need it there ?

Comment 31

[Nathan Froyd [:froydnj]]

(In reply to bhavana bajaj [:bajaj] from comment #30)
> (In reply to Nathan Froyd (:froydnj) from comment #29)
> > Risk to taking this patch (and alternatives if risky): Little risk.
> 
> Can you please expand a bit more on the risk here, what could be the worst
> thing that may happen ? 

The worst thing that could happen is that Telemetry would somehow get shut off, but we'd notice that after about a week or so of the patch landing.  So we'd have time to back out/fix.

> Considering this is a last week of aurora and this seems a huge uplift right
> before the merge, are we worried about stability ?Also is this strictly
> being uplifted to help with FHR and how badly do we need it there ?

Stability of the browser shouldn't be a problem with these patches.

FHR records several pieces of data at browser shutdown, such as how long FHR shutdown takes.  Due to bad interactions with Telemetry, we're not getting any visibility on that data.  There's also some networking cache telemetry that we don't have any visibility into.

There's a much shorter fix that could be landed on Aurora, roughly equivalent to part 5 and part 6 of the above patch series.  Would you prefer that instead?

Comment 32

[bhavana bajaj [:bajaj]]

(In reply to Nathan Froyd (:froydnj) from comment #31)
> (In reply to bhavana bajaj [:bajaj] from comment #30)
> > (In reply to Nathan Froyd (:froydnj) from comment #29)
> > > Risk to taking this patch (and alternatives if risky): Little risk.
> > 
> > Can you please expand a bit more on the risk here, what could be the worst
> > thing that may happen ? 
> 
> The worst thing that could happen is that Telemetry would somehow get shut
> off, but we'd notice that after about a week or so of the patch landing.  So
> we'd have time to back out/fix.
> 
> > Considering this is a last week of aurora and this seems a huge uplift right
> > before the merge, are we worried about stability ?Also is this strictly
> > being uplifted to help with FHR and how badly do we need it there ?
> 
> Stability of the browser shouldn't be a problem with these patches.
> 
> FHR records several pieces of data at browser shutdown, such as how long FHR
> shutdown takes.  Due to bad interactions with Telemetry, we're not getting
> any visibility on that data.  There's also some networking cache telemetry
> that we don't have any visibility into.
> 
> There's a much shorter fix that could be landed on Aurora, roughly
> equivalent to part 5 and part 6 of the above patch series.  Would you prefer
> that instead?

If that workaround solves the purpose here and is even slightly less riskier I think we should go with that option at this time.

Comment 33

[Nathan Froyd [:froydnj]]

Attachment: part 6 - switch saving pings over to profile-before-change2

Here's a much simpler patch for Aurora uplift only.  Instead of using all
the complicated machinery, we simply move ping saving to profile-before-change2.
Which is probably what I should have done once Benjamin said that adding a
new notification was OK.

Comment 34

[Nathan Froyd [:froydnj]]

Comment on attachment 730703 [details] [diff] [review]
part 6 - switch saving pings over to profile-before-change2

Here's a much simpler patch that, in conjunction with part 5, would implement the minimum that we would need for an Aurora uplift.  Taking part 5 and part 6 on Aurora would be much more palatable than the full series.  See comment 31 especially for why uplifting these would be a good thing.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): None.
User impact if declined: None.
Testing completed (on m-c, etc.): Local testing OK.
Risk to taking this patch (and alternatives if risky): No patch is risk free; this patch has low risk.
String or IDL/UUID changes made by this patch: None.

Comment 35

[bhavana bajaj [:bajaj]]

Comment on attachment 730703 [details] [diff] [review]
part 6 - switch saving pings over to profile-before-change2

low risk patch, helps FHR get visibility into shutdown data.

Thanks for the alternative patches here for aurora, please keep an eye on any regressions this may cause due to less baketime on aurora.

Comment 36

[Nathan Froyd [:froydnj]]

remote:   https://hg.mozilla.org/releases/mozilla-aurora/rev/643f2a754972
remote:   https://hg.mozilla.org/releases/mozilla-aurora/rev/da9a2b8a16cc

Comment 37

[Nathan Froyd [:froydnj]]

Attachment: Back out 80034b418a48 (bug 844331, part 6) on suspicion of breaking Telemetry submission

This bug looks like a very likely candidate for breaking Telemetry submissions
starting around the 19th of February.  This patch backs out the last part of
the patch series.

I realize the expected thing to do would be to back out the entire patch series.
However, this is the only patch that actually changes any behavior; the others
are merely rearranging code.  I also verified using the debugger that the
functions the other patches affected are still working properly and not throwing
errors.  So this is really the only patch that matters...

Comment 38

[Nathan Froyd [:froydnj]]

Backed out part 6: https://hg.mozilla.org/integration/mozilla-inbound/rev/322dcd797401

Verified on Windows that backing out that patch is sufficient to restore saving of telemetry pings.

It's possible that the patch we uplifted to FF21 (now on beta) is really the right way to go.  Will try that next.

Comment 39

[Ryan VanderMeulen [:RyanVM]]

(In reply to Nathan Froyd (:froydnj) from comment #38)
> Backed out part 6:
> https://hg.mozilla.org/integration/mozilla-inbound/rev/322dcd797401

https://hg.mozilla.org/mozilla-central/rev/322dcd797401

Comment 40

[Nathan Froyd [:froydnj]]

Comment on attachment 732016 [details] [diff] [review]
Back out 80034b418a48 (bug 844331, part 6) on suspicion of breaking Telemetry submission

It turns out that the patches from this bug that were landed late in the last release cycle on m-c markedly lowered telemetry submission rates.  This patch landed on m-c ~1 week ago and telemetry submission rates have shown a significant uptick.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 844331
User impact if declined: None
Testing completed (on m-c, etc.): On m-c for > 1 week.  Has markedly improved telemetry submission rates.
Risk to taking this patch (and alternatives if risky): None. 
String or IDL/UUID changes made by this patch: None

Comment 41

[Alex Keybl [:akeybl]]

Comment on attachment 732016 [details] [diff] [review]
Back out 80034b418a48 (bug 844331, part 6) on suspicion of breaking Telemetry submission

Always willing to take fixes in support of our metrics when low risk :)

Comment 42

[Nathan Froyd [:froydnj]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/cbd5eed919a6

Comment 43

[Mike Connor [:mconnor]]

I filed bug 862599 on what looks to be a regression on Beta caused by this patch.

Comment 44

[Nathan Froyd [:froydnj]]

Attachment: save pings in profile-before-change2 (once bug 867401 gets committed)

bug 867401 eliminates the issues with saving pings in profile-before-change2.
This patch, therefore, moves the saving of pings to profile-before-change2.
I've verified on Windows that we do save pings with these changes.

Comment 45

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/7655dd458b82

Comment 46

[Georg Fritzsche [:gfritzsche]]

Per comment 44 the last outstanding patch here got landed.