[Session Restore] More Telemetry on Session Restore startup

VERIFIED FIXED in Firefox 32

Status

()

defect
VERIFIED FIXED
5 years ago
5 years ago

People

(Reporter: Yoric, Assigned: Yoric)

Tracking

(Blocks 2 bugs, {perf})

unspecified
Firefox 32
Points:
---
Dependency tree / graph
Bug Flags:
firefox-backlog +

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: p=0 s=it-32c-31a-30b.2 [qa-])

Attachments

(1 attachment, 5 obsolete attachments)

Get telemetry probes in place that will let us monitor regressions such as bug 959130.
Blocks: fxdesktopbacklog
No longer blocks: fxdesktoptriage
Whiteboard: p=0
Once bug 936630 has landed, we will have the following timeline events:
- sessionRestoreInit
- sessionRestoreInitialized
- sessionRestoreRestoring
- sessionRestoreRestored.

I believe that we need the following data:
- how long it takes to read sessionstore.js (we already have it as FX_SESSION_RESTORE_READ_FILE_MS);
- how long it takes to parse sessionstore.js;
- how long it takes to process it;
- how long it takes to perform all DOM operations that are required before the user can browse (sessionRestoreRestored - sessionRestoreInit).
Depends on: 936630
No longer blocks: fxdesktopbacklog
Flags: firefox-backlog+
Whiteboard: p=0 → p=2
Assignee: nobody → dteller
Attachment #8417306 - Flags: review?(ttaubert)
Comment on attachment 8417306 [details] [diff] [review]
More telemetry on session restore startup

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

::: browser/components/sessionstore/src/SessionStore.jsm
@@ +759,5 @@
>      // ignore windows opened while shutting down
>      if (this._loadState == STATE_QUITTING)
>        return;
>  
> +    try {

OMG no, we can't do that. We should not wrap all that in try/catch and at the same time throw away all blame info. We have a real problem if we throw in onLoad() anyway.

@@ +760,5 @@
>      if (this._loadState == STATE_QUITTING)
>        return;
>  
> +    try {
> +      TelemetryStopwatch.start("FX_SESSION_RESTORE_STARTUP_PERFORM_DELAYED_RESTORATION_MS");

onLoad() is called for each window that we do or do not restore into. Maybe measure the .onLoad() call in onOpen() if |initialState| is not null?

::: toolkit/components/telemetry/Histograms.json
@@ +3343,5 @@
> +    "kind": "exponential",
> +    "high": "30000",
> +    "n_buckets": 20,
> +    "extended_statistics_ok": true,
> +    "description": "Session restore: Time it takes to finish restoration once we have first openeed a window (ms)"

*opened
Attachment #8417306 - Flags: review?(ttaubert) → review-
(In reply to Tim Taubert [:ttaubert] from comment #3)
> Comment on attachment 8417306 [details] [diff] [review]
> More telemetry on session restore startup
> 
> Review of attachment 8417306 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: browser/components/sessionstore/src/SessionStore.jsm
> @@ +759,5 @@
> >      // ignore windows opened while shutting down
> >      if (this._loadState == STATE_QUITTING)
> >        return;
> >  
> > +    try {
> 
> OMG no, we can't do that. We should not wrap all that in try/catch and at
> the same time throw away all blame info. We have a real problem if we throw
> in onLoad() anyway.

Hey, where do you see a `catch` in my code? :)
Attachment #8417306 - Attachment is obsolete: true
Attachment #8417397 - Flags: review?(ttaubert)
Same one, without bits of the next patch.
Attachment #8417397 - Attachment is obsolete: true
Attachment #8417397 - Flags: review?(ttaubert)
Attachment #8417398 - Flags: review?(ttaubert)
(and again)
Attachment #8417398 - Attachment is obsolete: true
Attachment #8417398 - Flags: review?(ttaubert)
Attachment #8417399 - Flags: review?(ttaubert)
Comment on attachment 8417399 [details] [diff] [review]
More telemetry on session restore startup, v4

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

::: browser/components/sessionstore/src/SessionStore.jsm
@@ +815,5 @@
>          // The next delayed save request should execute immediately.
>          SessionSaver.clearLastSaveTime();
>        }
> +    } else if (!this._isWindowLoaded(aWindow)) {
> +      // this window was opened by _openWindowWithState

I'd rather have us not do these tiny cleanups and keep the blame info.

@@ +979,5 @@
> +
> +            this.onLoad(aWindow, initialState);
> +          } finally {
> +            TelemetryStopwatch.finish("FX_SESSION_RESTORE_STARTUP_PERFORM_FIRST_LOAD_MS");
> +          }

No need to try/finally this.

::: toolkit/components/telemetry/Histograms.json
@@ +3333,5 @@
> +  "FX_SESSION_RESTORE_STARTUP_INIT_RESTORATION_MS": {
> +    "expires_in_version": "never",
> +    "kind": "exponential",
> +    "high": "30000",
> +    "n_buckets": 120,

Did you mean 120 buckets? 20 should be enough?
Attachment #8417399 - Flags: review?(ttaubert) → feedback+
Attachment #8417399 - Attachment is obsolete: true
Attachment #8417419 - Flags: review?(ttaubert)
Comment on attachment 8417419 [details] [diff] [review]
More telemetry on session restore startup, v5

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

::: browser/components/sessionstore/src/SessionStore.jsm
@@ +384,5 @@
>    /**
>     * Initialize the session using the state provided by SessionStartup
>     */
>    initSession: function () {
> +    TelemetryStopwatch.start("FX_SESSION_RESTORE_STARTUP_INIT_RESTORATION_MS");

Can you please call this ...INIT_SESSION_MS?

@@ +979,5 @@
>          } else {
>            let initialState = this.initSession();
>            this._sessionInitialized = true;
> +
> +          TelemetryStopwatch.start("FX_SESSION_RESTORE_STARTUP_PERFORM_FIRST_LOAD_MS");

This maybe... FX_SESSION_RESTORE_STARTUP_ONLOAD_INITIAL_WINDOW_MS?

::: toolkit/components/telemetry/Histograms.json
@@ +3333,5 @@
> +  "FX_SESSION_RESTORE_STARTUP_INIT_RESTORATION_MS": {
> +    "expires_in_version": "never",
> +    "kind": "exponential",
> +    "high": "30000",
> +    "n_buckets": 120,

Is that 120 buckets intentional or not?
Attachment #8417419 - Flags: review?(ttaubert)
> ::: toolkit/components/telemetry/Histograms.json
> @@ +3333,5 @@
> > +  "FX_SESSION_RESTORE_STARTUP_INIT_RESTORATION_MS": {
> > +    "expires_in_version": "never",
> > +    "kind": "exponential",
> > +    "high": "30000",
> > +    "n_buckets": 120,
> 
> Is that 120 buckets intentional or not?

My bad, I thought I had removed that.
Attachment #8417419 - Attachment is obsolete: true
Attachment #8417455 - Flags: review?(ttaubert)
Comment on attachment 8417455 [details] [diff] [review]
More telemetry on session restore startup, v6

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

::: browser/components/sessionstore/src/SessionStore.jsm
@@ +395,1 @@
>      }

The bad thing here is that even with a broken state (invalid session file that's not parseable) we can end up with ss.doRestore() returning true. We either need the try here or fix nsSessionStartup to check |this._initialState| and set sessionType to NO_SESSION. I'd very much prefer the latter. We should also have an xpcshell test similar to test_startup_invalid_session.js that sets browser.startup.page=3 and checks that we still get NO_SESSION with an unparseable file.
Attachment #8417455 - Flags: review?(ttaubert) → review-
Is that the right bug to handle this issue? I simply removed a try/catch block that can't raise.
Comment on attachment 8417455 [details] [diff] [review]
More telemetry on session restore startup, v6

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

Ignore me, sorry.
Attachment #8417455 - Flags: review- → review+
https://hg.mozilla.org/mozilla-central/rev/c0f79a8812c1
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Whiteboard: p=2[fixed-in-fx-team] → p=2
Target Milestone: --- → Firefox 32
Whiteboard: p=2 → p=0 s=it-32c-31a-30b.2 [qa?]
Whiteboard: p=0 s=it-32c-31a-30b.2 [qa?] → p=0 s=it-32c-31a-30b.2 [qa-]
Status: RESOLVED → VERIFIED
According to http://raluca-elena.github.io/telemetry-dashboard/#filter=nightly%2F32%2FFX_SESSION_RESTORE_READ_FILE_MS!nightly%2F32%2FFX_SESSION_RESTORE_STARTUP_INIT_SESSION_MS!nightly%2F32%2FFX_SESSION_RESTORE_STARTUP_ONLOAD_INITIAL_WINDOW_MS&aggregates=95th%20percentile&evoOver=Builds&locked=false&sanitize=true, on Nightly 32, FX_SESSION_RESTORE_READ_FILE_MS is by far the dominant cost over FX_SESSION_RESTORE_READ_FILE_MS and FX_SESSION_RESTORE_STARTUP_INIT_SESSION_MS.

This suggests that we should concentrate our efforts on reading faster, i.e.:
- reading earlier; and/or
- making the file smaller.
You need to log in before you can comment on or make changes to this bug.