779298 - shutdownduration is not reported

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[(dormant account)]

http://mxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/TelemetryPing.js#138 is landed yet,
there is no .shutdownDuration in my saved-telemetry-pings dir.

I also have Telemetry.ShutdownTime.txt, so the flaw is somewhere in bug 756142. There is also no data coming through telemetry dashboard, so it's likely I'm not the only one affected.

Comment 1

[Nathan Froyd [:froydnj]]

What are the contents of your Telemetry.ShutdownTime.txt file?

Comment 2

[(dormant account)]

(In reply to Nathan Froyd (:froydnj) from comment #1)
> What are the contents of your Telemetry.ShutdownTime.txt file?

"10249"

Comment 3

[Nathan Froyd [:froydnj]]

Attachment: part 1 - store file in the correct location

For whatever reason, we were storing the file in the prefs directory, rather than the profile directory.  I don't fully understand the ins and outs here, as the two directories are the same (?), but switching makes it more consistent with the rest of the codebase and enables us to actually test this stuff.

I think I can harass Doug as a Toolkit peer for review on this one.

Comment 4

[Nathan Froyd [:froydnj]]

Attachment: part 2 - fix fetching the value

...and the thinko part: it's not the startupInfo that holds the field, it's the actual service.  Fix that, and add a test to try and ensure we don't screw up later.

Comment 5

[Doug Turner (:dougt)]

Comment on attachment 647974 [details] [diff] [review]
part 1 - store file in the correct location

Yup.  Caused by bug 756142.  Nice catch. :)

Comment 6

[(dormant account)]

Comment on attachment 647975 [details] [diff] [review]
part 2 - fix fetching the value

What about the fact that my shutdowntime.txt contains 10249 VS 1919251566 value returned by lastShutdownDuration

Comment 7

[(dormant account)]

Comment on attachment 647975 [details] [diff] [review]
part 2 - fix fetching the value

+  do_check_true(payload.simpleMeasurements.shutdownDuration == SHUTDOWN_TIME);
that should be do_check_eq

Comment 8

[(dormant account)]

Comment on attachment 647974 [details] [diff] [review]
part 1 - store file in the correct location

I actually think we should store the file in saved-telemetry-pings directory. Would make sense to group all of the weird telemetry-motivated data together.

Comment 9

[Nathan Froyd [:froydnj]]

(In reply to Taras Glek (:taras) from comment #6)
> What about the fact that my shutdowntime.txt contains 10249 VS 1919251566
> value returned by lastShutdownDuration

That's just weird.  I don't know what's going on with your machine.  Your machine is Windows?  Should do a try push tomorrow just to make sure this isn't going to break something.

(In reply to Taras Glek (:taras) from comment #8)
> I actually think we should store the file in saved-telemetry-pings
> directory. Would make sense to group all of the weird telemetry-motivated
> data together.

Not a bad idea, but it would require some tweaking to how we enumerate pings and I'd rather not do that here.  If you want to file a followup bug, we can discuss.

Comment 10

[Nathan Froyd [:froydnj]]

For reasons I do not understand, the new test is consistently failing everywhere:

https://tbpl.mozilla.org/?tree=Try&rev=5d487fda7200

even though it passes just fine locally.

Comment 11

[Nathan Froyd [:froydnj]]

Even after being a little more careful with safe file output, things are still falling over:

https://tbpl.mozilla.org/?tree=Try&rev=4ea59ed6b766

Notice especially the WinXP log, which seems to show problems similar to comment 6.

This test also seems to make bug 764030 happen quite a bit more often.

Comment 12

[Nathan Froyd [:froydnj]]

Attachment: part 1 - store file in the correct location; brownbag fix

Testing revealed that I had forgotten to initialize the new member variables added in bug 756142.  I think this is obvious/brownbaggish enough that I'm just rolling that fix into part 1, sans re-review.

Comment 13

[Nathan Froyd [:froydnj]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/5bd90df027d0
https://hg.mozilla.org/integration/mozilla-inbound/rev/c4b249ca469b

Comment 14

[Ed Morley [:emorley]]

Backed out for assertions on OS X:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&onlyunstarred=1&rev=c4b249ca469b

https://hg.mozilla.org/integration/mozilla-inbound/rev/4392d5928cf1

Comment 15

[Ed Morley [:emorley]]

bah, s/&onlyunstarred=1//

Comment 16

[Nathan Froyd [:froydnj]]

Attachment: fix test bustage

I believe this patch fixes the bustage seen on Inbound; it's currently running on Try and seems plausible enough.  I forgot that M-oth tests touch Telemetry and should have been exercised prior to committing.

The problem is that recording the timestamp assumes that if the filename of the timestamp file has been computed, then that must mean that we recorded a start time.  However, if we have:

- a build without telemetry enabled;
- we access lastShutdownDuration (thereby computing the filename to try and read the file;
- we shutdown;

then we try to compute the different between TimeStamp::Now() and the start time.  Except that the start time is a null TimeStamp, because we never set it earlier.  And kaboom on debug builds.

This patch is one way to fix that.  The other is adding an explicit flag to say "yes, we recorded a start time" rather than relying on the filename to serve as such.

Comment 17

[Nathan Froyd [:froydnj]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/28944cefdd3c
https://hg.mozilla.org/integration/mozilla-inbound/rev/497806930eb6

Comment 18

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/28944cefdd3c
https://hg.mozilla.org/mozilla-central/rev/497806930eb6