833612 - Session restored time being reported as -1

Status: VERIFIED FIXED

(Firefox Health Report Graveyard :: Client: Desktop, defect)

Description

[Gregory Szorc [:gps]]

I'm seeing this in official Nightly builds on both OS X and Windows. Local builds work fine (at least they did just before I checked bug 827157 in). Not sure what's going on.

FWIW, the -1 comes from the default value when doing a prefs.get(). The underlying problem is the current.sessionRestored pref is not being set.

We really need a mochitest or marionette test for this...

Comment 1

[Gregory Szorc [:gps]]

Attachment: More robust collection of sessionRestored, v1

Since apparently nextTick wasn't enough to capture sessionRestored in sessionstore-windows-restored, we now install a recurring timer and attempt to get sessionRestored until it is available.

Comment 2

[Gregory Szorc [:gps]]

Daniel: Can you please confirm that we are seeing sessionRestored == -1 on actual payloads in Nightly?

Comment 3

[Daniel Einspanjer [:dre] [:deinspanjer]]

Harsha, is this something you could dig up out of the latest FHR payloads today?

Comment 4

[Harsha [:harsha]]

Daniel,
   I will work on it.
-Harsha

Comment 5

[Harsha [:harsha]]

Gregory,
     We have 2000 payloads with org.mozilla.appSessions.current.sessionRestored as -1 out of total 93177 records.
Let me know if you need more info regarding those payloads.

Thanks
Harsha

Comment 6

[Richard Newman [:rnewman]]

Comment on attachment 709168 [details] [diff] [review]
More robust collection of sessionRestored, v1

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

::: services/datareporting/sessions.jsm
@@ +206,3 @@
>  
>    recordStartupFields: function () {
>      let si = this._getStartupInfo();

We're now calling recordStartupFields up to 60 times.

getStartupInfo appears to accumulate some telemetry info (e.g., STARTUP_MEASUREMENT_ERRORS). Please make sure with the telemetry folks that potentially accumulating a few dozen times is OK…

@@ +297,5 @@
>  
> +    if (this._timer) {
> +      this._timer.cancel();
> +      delete this._timer;
> +    }

These four lines are repeated twice. Refactor into method?

::: services/datareporting/tests/xpcshell/test_session_recorder.js
@@ +124,5 @@
> +  do_check_null(recorder._timer);
> +  yield sleep(100);
> +  do_check_eq(recordCount, 4);
> +
> +  recorder.onShutdown();

Need a test that shutdown clears the timer, too.

Comment 7

[Gregory Szorc [:gps]]

Comment on attachment 709168 [details] [diff] [review]
More robust collection of sessionRestored, v1

Could one of you please comment on the effect to Telemetry of calling getStartupInfo() multiple times?

I may land this before feedback is granted. If it makes it to m-c, we can do a follow-up or back out (at worst).

Comment 8

[Gregory Szorc [:gps]]

https://hg.mozilla.org/services/services-central/rev/916d0e440c47

With new test and with timer clearing factored into a function.

Will address Telemetry/Perf issue if it is flagged.

Comment 9

[Gregory Szorc [:gps]]

https://hg.mozilla.org/mozilla-central/rev/916d0e440c47

Comment 10

[Vladan Djeric (:vladan)]

Comment on attachment 709168 [details] [diff] [review]
More robust collection of sessionRestored, v1

Calling getStartupInfo repeatedly won't skew the STARTUP_MEASUREMENT_ERRORS data.

What is causing these startup timestamps to be missing?
Is it that a) the startup timestamp is corrupted or incorrect for whatever reason, or b) the startup event in question hasn't occurred yet when FHR tries to get its timestamp?

Comment 11

[Gregory Szorc [:gps]]

(In reply to Vladan Djeric (:vladan) from comment #10)
> What is causing these startup timestamps to be missing?
> b) the startup event in question hasn't occurred yet when FHR
> tries to get its timestamp?

This one. Apparently there is a race condition between the order the observers are registered in or something. It always works for my local builds and apparently works for a number of users in the wild. However, a significant fraction of reports contained -1. So, we had to resort to polling :(

Comment 12

[u279076]

Verifed fixed in Aurora 21.0a2. Marking in-testsuite+ since it appears this patch landed with tests. Please correct me if I am wrong.