896545 - [Session Restore] Telemetry on TabStateCache efficiency

Status: RESOLVED FIXED

(Firefox :: Session Restore, defect)

Description

[David Teller [:Yoric] - still alive but not very active]

Bug 867143 introduces a cache for Session Restore. We should determine how often we hit/miss on the cache.

Comment 1

[David Teller [:Yoric] - still alive but not very active]

Telemetry ( http://tinyurl.com/mfsw43x ) doesn't show any meaningful improvement. We should find out why.

Comment 2

[David Teller [:Yoric] - still alive but not very active]

Attachment: Telemetry on TabStateCache hit/miss

Attaching a first prototype.

Comment 3

[Nathan Froyd [:froydnj]]

Comment on attachment 794014 [details] [diff] [review]
Telemetry on TabStateCache hit/miss

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

Looks OK, although clearly a first draft. :)

::: browser/components/sessionstore/src/SessionStore.jsm
@@ +4773,5 @@
> +     *
> +     * @param {boolean} isHit If |true|, the access was a hit, otherwise
> +     * a miss.
> +     */
> +    recordAccess: function(isHit) {

Looks like you need to call this somewhere.

@@ +4804,5 @@
> +      if (this._initialized) {
> +        return;
> +      }
> +      let observer = () => {
> +        Services.obs.removeObserver(observer, "gather-telemetry");

On a long running session, you're only going to execute this observer once.  Is that OK?

::: toolkit/components/telemetry/Histograms.json
@@ +2524,5 @@
>      "n_buckets": 10,
>      "extended_statistics_ok": true,
>      "description": "Session restore: Time to read the session data from the file on disk, using the synchronous fallback (ms)"
>    },
> +  "FX_SESSION_RESTORE_TABSTATECACHE_HITS": {

AFAICS you don't use this histogram.

@@ +2567,5 @@
>      "description": "Session restore: Days elapsed since the session was first started"
>    },
> +  "FX_SESSION_RESTORE_TABSTATECACHE_HIT_RATE": {
> +     "kind": "enumerated",
> +     "n_values": 101,

You can make this 100 even.

@@ +2574,5 @@
> +  "FX_SESSION_RESTORE_TABSTATECACHE_CLEARS": {
> +     "kind": "exponential",
> +     "n_buckets": 20,
> +      "high": 1000,
> +     "description": "Session restore: Percentage of tab state cache hits in all tab state cache accesses",

This string does not describe the histogram it is associated with.

Comment 4

[David Teller [:Yoric] - still alive but not very active]

Attachment: Telemetry on TabStateCache hit/miss, v2

Comment 5

[Nathan Froyd [:froydnj]]

Comment on attachment 794021 [details] [diff] [review]
Telemetry on TabStateCache hit/miss, v2

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

Better.

::: browser/components/sessionstore/src/SessionStore.jsm
@@ +4715,5 @@
>     */
>    get: function(aKey) {
>      let key = this._normalizeToBrowser(aKey);
> +    let result = this._data.get(key);
> +    this._telemetry.recordAccess(!!result);

Maybe you want to pull out this._data.get() and the recordAccess into a separate function, so somebody doesn't go adding _data.get() calls without hitting telemetry?  (They could still do that, but maybe cargo-culting would prevent it...)

@@ +4731,2 @@
>      let key = this._normalizeToBrowser(aKey);
>      this._data.delete(key);

Do you want a separate histogram for cache deletes, too?

@@ +4805,5 @@
> +      if (this._initialized) {
> +        return;
> +      }
> +      let observer = () => {
> +        Services.obs.removeObserver(observer, "gather-telemetry");

Still recording this only once per session...

Comment 6

[Tim Taubert [:ttaubert] (inactive)]

Comment on attachment 794021 [details] [diff] [review]
Telemetry on TabStateCache hit/miss, v2

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

::: browser/components/sessionstore/src/SessionStore.jsm
@@ +4767,5 @@
>      }
>      throw new TypeError("Key is neither a tab nor a browser: " + nodeName);
> +  },
> +
> +  _telemetry: {

Put this in a separate TabStateCacheTelemetry object maybe?

@@ +4803,5 @@
> +     */
> +    _init: function() {
> +      if (this._initialized) {
> +        return;
> +      }

The whole lazy initialization could also just be an _addObserver() method that turns itself into a no-op after the first call.

@@ +4820,5 @@
> +        // Record number of cache clears
> +        let histo = Services.telemetry.getHistogramById(PREFIX + "CLEARS");
> +        histo.add(this._clears);
> +      };
> +      Services.obs.addObserver(observer, "gather-telemetry", false);

Calling addObserver(this, "gather-telemetry", false) and adding an observe() method should make this look a little cleaner.

::: toolkit/components/telemetry/Histograms.json
@@ +2564,5 @@
>      "description": "Session restore: Days elapsed since the session was first started"
>    },
> +  "FX_SESSION_RESTORE_TABSTATECACHE_HIT_RATE": {
> +     "kind": "enumerated",
> +     "n_values": 101,

Is there a reason this is 101? Is this an upper/exclusive bound?

@@ +2570,5 @@
> +  },
> +  "FX_SESSION_RESTORE_TABSTATECACHE_CLEARS": {
> +     "kind": "exponential",
> +     "n_buckets": 20,
> +      "high": 1000,

Nit: indentation is off.

Comment 7

[David Teller [:Yoric] - still alive but not very active]

(In reply to Tim Taubert [:ttaubert] from comment #6)
> Comment on attachment 794021 [details] [diff] [review]
> Telemetry on TabStateCache hit/miss, v2
> 
> Review of attachment 794021 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: browser/components/sessionstore/src/SessionStore.jsm
> @@ +4767,5 @@
> >      }
> >      throw new TypeError("Key is neither a tab nor a browser: " + nodeName);
> > +  },
> > +
> > +  _telemetry: {
> 
> Put this in a separate TabStateCacheTelemetry object maybe?

I believe that this would be overkill for such a small object.

> 
> @@ +4803,5 @@
> > +     */
> > +    _init: function() {
> > +      if (this._initialized) {
> > +        return;
> > +      }
> 
> The whole lazy initialization could also just be an _addObserver() method
> that turns itself into a no-op after the first call.

Called by whom?

> ::: toolkit/components/telemetry/Histograms.json
> @@ +2564,5 @@
> >      "description": "Session restore: Days elapsed since the session was first started"
> >    },
> > +  "FX_SESSION_RESTORE_TABSTATECACHE_HIT_RATE": {
> > +     "kind": "enumerated",
> > +     "n_values": 101,
> 
> Is there a reason this is 101? Is this an upper/exclusive bound?

From 0 to 100 inclusive, so that's 101 values. I suspect we'll never get 100% because I round down, but I didn't want to rely upon this rounding behavior.

Comment 8

[Tim Taubert [:ttaubert] (inactive)]

(In reply to David Rajchenbach Teller [:Yoric] from comment #7)
> > Put this in a separate TabStateCacheTelemetry object maybe?
> 
> I believe that this would be overkill for such a small object.

I don't think so, it looks quite messy currently. It would be great to move TabStateCache to a separate module anyway in the future.

> > The whole lazy initialization could also just be an _addObserver() method
> > that turns itself into a no-op after the first call.
> 
> Called by whom?

By those functions that currently call _init().

> > Is there a reason this is 101? Is this an upper/exclusive bound?
> 
> From 0 to 100 inclusive, so that's 101 values. I suspect we'll never get
> 100% because I round down, but I didn't want to rely upon this rounding
> behavior.

Ah, right. Thanks for explaining.

Comment 9

[David Teller [:Yoric] - still alive but not very active]

Attachment: Telemetry on TabStateCache hit/miss, v3

Main changes:
- now using the profile-before-change notification;
- turned _telemetry into an object TabStateCacheTelemetry;
- initialization is now triggered by SessionRestoreInternal.init();
- replaced closure |observe| by TabStateCacheTelemetry itself;
- fixed typoes in Histograms.json.

Comment 10

[Tim Taubert [:ttaubert] (inactive)]

Comment on attachment 794573 [details] [diff] [review]
Telemetry on TabStateCache hit/miss, v3

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

::: browser/components/sessionstore/src/SessionStore.jsm
@@ +4698,5 @@
> +  init: function() {
> +    if (this._data) {
> +      // Avoid double initialization
> +      return;
> +    }

I kind of liked the lazy observer registration in TabStateCacheTelemetry itself as that decouples the submodules a little more but I'll leave that up to you...

@@ +4700,5 @@
> +      // Avoid double initialization
> +      return;
> +    }
> +    this._data = new WeakMap();
> +    Services.obs.addObserver(TabStateCacheTelemetry, "profile-before-change", false);

Will our telemetry still be sent before shutdown or is that done in the next session? Not sure that's relevant but I'm just curious. Do we retain telemetry data until the next start at all?

@@ +4800,5 @@
> +  },
> +  // Total number of hits during the session
> +  _hits: 0,
> +  // Total number of misses during the session
> +  _misses: 0,

Can we please move those fields to the top?

@@ +4809,5 @@
> +  recordClear: function() {
> +    ++this._clears;
> +  },
> +  // Total number of clears during the session
> +  _clears: 0,

Same here?

::: toolkit/components/osfile/tests/mochi/main_test_osfile_async.js
@@ +871,5 @@
>   * Test optional duration reporting that can be used for telemetry.
>   */
>  let test_duration = maketest("duration", function duration(test) {
>    return Task.spawn(function() {
> +    Services.prefs.setBoolPref("toolkit.osfile.log", true);

That change/file seems quite unrelated?

Comment 11

[David Teller [:Yoric] - still alive but not very active]

(In reply to Tim Taubert [:ttaubert] from comment #10)
> Comment on attachment 794573 [details] [diff] [review]
> Telemetry on TabStateCache hit/miss, v3
> 
> Review of attachment 794573 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: browser/components/sessionstore/src/SessionStore.jsm
> @@ +4698,5 @@
> > +  init: function() {
> > +    if (this._data) {
> > +      // Avoid double initialization
> > +      return;
> > +    }
> 
> I kind of liked the lazy observer registration in TabStateCacheTelemetry
> itself as that decouples the submodules a little more but I'll leave that up
> to you...

Done.

> 
> @@ +4700,5 @@
> > +      // Avoid double initialization
> > +      return;
> > +    }
> > +    this._data = new WeakMap();
> > +    Services.obs.addObserver(TabStateCacheTelemetry, "profile-before-change", false);
> 
> Will our telemetry still be sent before shutdown or is that done in the next
> session? Not sure that's relevant but I'm just curious. Do we retain
> telemetry data until the next start at all?

I believe that we're not sending the data immediately but that it will be saved and used at the next "gather-telemetry".

> ::: toolkit/components/osfile/tests/mochi/main_test_osfile_async.js
> @@ +871,5 @@
> >   * Test optional duration reporting that can be used for telemetry.
> >   */
> >  let test_duration = maketest("duration", function duration(test) {
> >    return Task.spawn(function() {
> > +    Services.prefs.setBoolPref("toolkit.osfile.log", true);
> 
> That change/file seems quite unrelated?

Sorry about that.

Comment 12

[David Teller [:Yoric] - still alive but not very active]

Attachment: Telemetry on TabStateCache hit/miss, v4

Applied your feedback, changed the measure a little.

Comment 13

[Tim Taubert [:ttaubert] (inactive)]

Comment on attachment 795402 [details] [diff] [review]
Telemetry on TabStateCache hit/miss, v4

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

::: browser/components/sessionstore/src/SessionStore.jsm
@@ +4699,5 @@
> +      // Avoid double initialization
> +      return;
> +    }
> +    this._data = new WeakMap();
> +    Services.obs.addObserver(TabStateCacheTelemetry, "profile-before-change", false);

This seems like it would be easier to have a TabStateCacheTelemetry._init() method that is called by recordClear() and recordAccess(). We don't really need an initializer for TabStateCache.

::: toolkit/components/telemetry/Histograms.json
@@ +2567,5 @@
> +     "kind": "enumerated",
> +     "n_values": 101,
> +     "description": "Session restore: Percentage of tab state cache hits in all tab state cache accesses"
> +  },
> +  "FX_SESSION_RESTORE_TABSTATECACHE_CLEARS": {

maybe CLEAR_RATIO/RATE or something?

@@ +2570,5 @@
> +  },
> +  "FX_SESSION_RESTORE_TABSTATECACHE_CLEARS": {
> +     "kind": "exponential",
> +     "n_buckets": 20,
> +     "n_values": 101,

We don't need n_buckets when we have n_values, do we?

Comment 14

[David Teller [:Yoric] - still alive but not very active]

Attachment: Telemetry on TabStateCache hit/miss, v4.1

Same patch, minus typo.

Comment 15

[Tim Taubert [:ttaubert] (inactive)]

Comment on attachment 796670 [details] [diff] [review]
Telemetry on TabStateCache hit/miss, v4.1

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

::: browser/components/sessionstore/src/SessionStore.jsm
@@ +4750,5 @@
> +    }
> +    Services.obs.addObserver(this, "profile-before-change", false);
> +  },
> +
> +  },

That shouldn't work :)

@@ +4769,5 @@
> +
> +    // Record number of cache clears
> +    histo = Services.telemetry.getHistogramById(PREFIX + "CLEARS");
> +    rate = Math.floor( ( this._clears * 100 ) / accesses );
> +    histo.add(rate);

This seems like it can be moved to a separate function that you pass the 'postfix' of the histogram id and the number of events.

::: toolkit/components/telemetry/Histograms.json
@@ +2567,5 @@
> +     "kind": "enumerated",
> +     "n_values": 101,
> +     "description": "Session restore: Percentage of tab state cache hits in all tab state cache accesses"
> +  },
> +  "FX_SESSION_RESTORE_TABSTATECACHE_CLEARS": {

maybe CLEAR_RATIO/RATE or something? It's not an absolute number anymore.

Comment 16

[David Teller [:Yoric] - still alive but not very active]

Attachment: Telemetry on TabStateCache hit/miss, v5

Applied feedback.

Comment 17

[David Teller [:Yoric] - still alive but not very active]

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

Comment 18

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/fx-team/rev/38950e6974b9

Comment 19

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/38950e6974b9

Comment 20

[David Teller [:Yoric] - still alive but not very active]

Telemetry seems to indicate that the TabStateCache hits quite frequently so all is good on that front.
However, bug 912717 seems to indicate that SessionCookie might be the culprit.