1425613 - Avoid repeatedly calling "manual" pref getters from JS for the same prefs

Status: RESOLVED FIXED

(Firefox :: General, enhancement, P3)

Description

[:Gijs (he/him)]

Attachment: sorted-callers.txt

get*Pref and friends can be expensive (cf. https://groups.google.com/forum/#!msg/mozilla.dev.platform/ZmHWTH_trrA/9-1i7eIjAAAJ;context-place=msg/mozilla.dev.platform/FyaPM_7FBfQ/SkIUG_e7Aw8J ).

We are still calling getBoolPref and friends manually hundreds of times even when just starting and stopping the browser.

We should stop doing that.

When running the url bar test directory in browser/base/content, the following top culprit files show up (numbers reflect number of calls to any methods on the nsIPrefBranch interface):

4773 ["resource://gre/modules/TelemetryEnvironment.jsm"
1695 ["chrome://browser/content/content-sessionStore.js"
1349 ["chrome://browser/content/tab-content.js"
1032 ["chrome://browser/content/browser.js"
 981 ["chrome://global/content/viewZoomOverlay.js"
 603 ["... components/nsSearchService.js"
 509 ["chrome://browser/content/browser-sync.js"
 506 ["resource://gre/modules/Preferences.jsm"
 405 ["resource://onboarding/onboarding.js"
 305 ["resource://gre/modules/XPCOMUtils.jsm"

Note that XPCOMUtils comes in 10th, which is 9 places lower than where I would expect it to be.

Pretty much all the other cases except Preferences.jsm (which we should be killing separately when/where we can...) probably have something dumb happening.

AFAICT full zoom, session restore, tab-content.js and browser.js probably have prefs that we look up for every tab instead of having a cache.

TelemetryEnvironment.jsm is just spectacular, in that it seems to have a set of prefs it cares about, it then has an observer that fires whenever any of the prefs changes, and then it re-fetches every single pref it cares about. It doesn't seem to use the contents of the nsPref:changed notification in any way.

Comment 1

[Thom Chiovoloni [:tcsc] (ex-moco)]

Can you attach the patch/script/whatever you used to generate this (or an explanation of what you did)?

I'm pretty sure there's an easy fix for browser-sync.js, but would like to ensure it fixes the issue.

Comment 2

[:Gijs (he/him)]

Attachment: Call sites patch

Sure, this is what I use. It modifies xpconnect to log callsites, in this case specifically the nsIPrefBranch ones, and it adds stacks for those.

To get the top callers, I basically used grep to filter out callsite JS(m) files and then sort + uniq -c

You could trivially update the patch to also log which methods get used, and/or grep line numbers and so on. I haven't tried very hard, it was Friday afternoon before the all-hands party. :-)

Comment 3

[Mark Hammond [:markh] [:mhammond]]

Depending on what pref observer overhead is, there might be scope for a "defineLazyPrefGetter" type helper(s) that both caches and observes for changes. IIRC, c++ has a fairly nice chaching helper, but JS doesn't.

Comment 4

[:Gijs (he/him)]

(In reply to Mark Hammond [:markh] from comment #3)
> Depending on what pref observer overhead is, there might be scope for a
> "defineLazyPrefGetter" type helper(s) that both caches and observes for
> changes. IIRC, c++ has a fairly nice chaching helper, but JS doesn't.

This already exists, it's XPCOMUtils.defineLazyPreferenceGetter() :-)

Comment 5

[Mark Hammond [:markh] [:mhammond]]

doh! I blame jet-lag :)

Comment 6

[Thom Chiovoloni [:tcsc] (ex-moco)]

Thanks, that confirms that my patch appears to fix the issue.

One difference I have from your output is that I have 2351 pref calls in nsSearchService.js, putting it the second place offender after TelemetryEnvironment. Everything else seems more or less the same though.

Comment 7

[:Gijs (he/him)]

Per e-mail discussion with :njn, just blindly replacing all the calls with JS pref caches isn't necessarily a good idea. We should be careful about not adding as many observers as we currently have get*Pref callsites - that would just make things worse. At the moment, it's not super clear to me where the "line" is...

What I *will* say, is that the callsites that are in framescripts probably want to move into a jsm so they have 1 cache per child process rather than being fetched N times per tab (for pretty much any N, really).

For callsites in the parent process that happen once per tab (or url load, or something like that), a cache seems reasonable to me, too (and although having just 1 for the entire Firefox rather than 1 per toplevel browser window would be better, even caching in browser.js or whatever would be better than the status quo). The other aspect to it is how often the pref realistically changes, I suppose. JS pref observers aren't directly hooked into the pref services like the C++ version is, and as a result having loads of observers probably isn't a great idea.

Perhaps in some cases we should have our own "cache" of the pref that simply doesn't update at runtime. I bet there are some prefs where there just really isn't a need to be "refreshing" them while running Firefox.

Alternatively, we could try to come up with a cheaper (compiled-code-powered) cache for JS that didn't rely on the observers.

Comment 8

[Kris Maglione [:kmag]]

(In reply to :Gijs from comment #7)
> Per e-mail discussion with :njn, just blindly replacing all the calls with
> JS pref caches isn't necessarily a good idea. We should be careful about not
> adding as many observers as we currently have get*Pref callsites - that
> would just make things worse. At the moment, it's not super clear to me
> where the "line" is...

If the preferences are used more than once, it should still be cheaper to use a
preference getter. Pref observers are cheap, as long as they aren't called, and
it looks like most of these pref accesses are the same pref being accessed many
times.

> The other aspect to it is how often the pref realistically changes, I suppose.
> JS pref observers aren't directly hooked into the pref services like the C++
> version is, and as a result having loads of observers probably isn't a great
> idea.

Having lots of observers is fine, as long as the pref doesn't change very often.

> Perhaps in some cases we should have our own "cache" of the pref that simply
> doesn't update at runtime. I bet there are some prefs where there just
> really isn't a need to be "refreshing" them while running Firefox.

I'd rather avoid this except in cases where we really need to.

> Alternatively, we could try to come up with a cheaper
> (compiled-code-powered) cache for JS that didn't rely on the observers.

We could do this, but let's wait until we have evidence that it's necessary. We
can always change `defineLazyPrefGetter` to use a native implementation if we
need to.

Comment 9

[:Gijs (he/him)]

(In reply to Kris Maglione [:kmag] (long backlog; ping on IRC if you're blocked) from comment #8)
> (In reply to :Gijs from comment #7)
> > The other aspect to it is how often the pref realistically changes, I suppose.
> > JS pref observers aren't directly hooked into the pref services like the C++
> > version is, and as a result having loads of observers probably isn't a great
> > idea.
> 
> Having lots of observers is fine, as long as the pref doesn't change very
> often.

From what I can tell, you and :njn disagree here. I don't have enough data to be arguing strongly either way, but I will note that, as far as I can tell:

- all pref observers are all kept in one single giant callback array
- any time *any* pref changes, we scan that entire giant callback array for any observer we need to notify

as a result, it feels to me like the observers do have both a memory and runtime cost, even if "the" pref they observe doesn't change (even at all!)? I agree that in many cases, that cost is lower than the cost of (repeated) pref fetches, but as I said previously, I wouldn't know exactly where the "line" is for swapping them over.

Comment 10

[Kris Maglione [:kmag]]

(In reply to :Gijs from comment #9)
> From what I can tell, you and :njn disagree here. I don't have enough data
> to be arguing strongly either way, but I will note that, as far as I can
> tell:
> 
> - all pref observers are all kept in one single giant callback array
> - any time *any* pref changes, we scan that entire giant callback array for
> any observer we need to notify
> 
> as a result, it feels to me like the observers do have both a memory and
> runtime cost, even if "the" pref they observe doesn't change (even at all!)?
> I agree that in many cases, that cost is lower than the cost of (repeated)
> pref fetches, but as I said previously, I wouldn't know exactly where the
> "line" is for swapping them over.

That's true, but the cost isn't much different for JS pref caches than it is for native pref caches. Either way, we need to scan the list of cached prefs whenever any pref changes. JS observers cost more, but only when an observed pref changes.

And prefs shouldn't be changing very often. If they are, that's probably the bug we should be looking to fix :)

Comment 11

[Thom Chiovoloni [:tcsc] (ex-moco)]

> And prefs shouldn't be changing very often. If they are, that's probably the bug we should be looking to fix :)

What would you consider often?

Sync in particular changes prefs fairly often. Using the attached script, a single sync (one that is probably typical in how much work it has to do -- syncs that have a lot to do will likely write more, and noop syncs will likely write less) seems to write about 50ish prefs. (Syncs happen frequently but not constantly, according to a one-off script that reads my local outgoing sync pings from TelemetryArchive, I do around 70 syncs a day -- my attempts to get less anecdotal data out of redash haven't been too successful, but that sounds about right for typical usage)

Anyway, there are some obvious ways to reduce this for sync's case (bug 1425960), but some of it is more or less necessary to the way sync currently functions, and so we'd need to find somewhere else to store that state if not prefs...

Is this often enough that it sounds like we should investigate some other method of storing our state?

Comment 12

[Kris Maglione [:kmag]]

(In reply to Thom Chiovoloni [:tcsc] from comment #11)
> > And prefs shouldn't be changing very often. If they are, that's probably the bug we should be looking to fix :)
> 
> What would you consider often?

I'd say, ideally, we shouldn't change more than a half dozen prefs in a session unless the user changes a setting.

> Sync in particular changes prefs fairly often. Using the attached script, a
> single sync (one that is probably typical in how much work it has to do --
> syncs that have a lot to do will likely write more, and noop syncs will
> likely write less) seems to write about 50ish prefs. (Syncs happen
> frequently but not constantly, according to a one-off script that reads my
> local outgoing sync pings from TelemetryArchive, I do around 70 syncs a day
> -- my attempts to get less anecdotal data out of redash haven't been too
> successful, but that sounds about right for typical usage)
> 
> Anyway, there are some obvious ways to reduce this for sync's case (bug
> 1425960), but some of it is more or less necessary to the way sync currently
> functions, and so we'd need to find somewhere else to store that state if
> not prefs...
>
> Is this often enough that it sounds like we should investigate some other
> method of storing our state?

Yes, if you're changing that many preferences, you should be using another datastore. Probably indexedDB. The preference system is really meant to store actual preference values, not arbitrary state data (as we tend to abuse it for). Writing to it is expensive.

Comment 13

[Johann Hofmann [:johannh]]

Attachment: Add a test for repeatedly called pref getters

This is a WIP attempt at writing a fast-for-good style test for this problem.
I'm hooking into the pref service and add another hashmap to count the
times a pref has been accessed. I think the results are quite interesting,
and it shows both C++ and JS callers.

The included test shows how we could use that interface, though I'm open for
suggestions. I also included a reset function so that we can test certain
scenarios, e.g. "I open 10 tabs".

Before I spend more time on this I'd like to verify that this is a good idea
or whether I'm running in the wrong direction. Maybe Gijs and njn can help me
figure that out.

Thanks!

Comment 14

[Kris Maglione [:kmag]]

Comment on attachment 8952025 [details] [diff] [review]
Add a test for repeatedly called pref getters

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

::: browser/base/content/test/performance/browser_preferences_usage.js
@@ +46,5 @@
> +      max: 350,
> +    },
> +    "layout.css.prefixes.webkit": {
> +      min: 140,
> +      max: 150,

These both seem... excessive...

Comment 15

[Nicholas Nethercote [inactive]]

Comment on attachment 8952025 [details] [diff] [review]
Add a test for repeatedly called pref getters

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

::: modules/libpref/Preferences.cpp
@@ +728,5 @@
>  };
>  
>  static PLDHashTable* gHashTable;
>  
> +#if defined(NIGHTLY_BUILD) || defined(DEBUG)

I strongly oppose having this in Nightly builds, because prefs is already a significant source of content process memory overhead and I am actively working on its memory usage.

But if it's debug builds only (as the comments in nsIPrefService.idl claim) that's probably ok.

@@ +729,5 @@
>  
>  static PLDHashTable* gHashTable;
>  
> +#if defined(NIGHTLY_BUILD) || defined(DEBUG)
> +static nsDataHashtable<nsCStringHashKey, uint32_t>* gPrefAccessStatsTable;

To reduce memory usage, you can just add the count to the existing hash table. Add a uint32_t field to PrefEntry. (Don't add it to Pref; I have plans to make Pref `static` and that would interfere.)

This change means that you wouldn't record counts for lookups of non-existent prefs. Perhaps you could have a global count of those without recording their actual names? Probably depends how common such lookups are.

@@ +851,5 @@
>  #endif
>  
> +#if defined(NIGHTLY_BUILD) || defined(DEBUG)
> +  nsCString key;
> +  key.Assign(aPrefName);

You can write these two lines as:

> nsCString key(aPrefName);

Comment 16

[:Gijs (he/him)]

Comment on attachment 8952025 [details] [diff] [review]
Add a test for repeatedly called pref getters

The test/JS side of this looks OK to me. I think a max of 40 for navigation and startup is quite high - 10 would be more reasonable, but we can file follow-ups to clamp down on this. I'm intrigued you set it to 15 for opening 10 tabs. This would preclude items that the tabbrowser (or other consumers) look up for every tab, which is something we can probably optimize more easily.

I expect the view-source.tab stuff to have gone away on an up-to-date tree given   https://bugzilla.mozilla.org/show_bug.cgi?id=1418403 .

(In reply to Kris Maglione [:kmag] (long backlog; ping on IRC if you're blocked) from comment #14)
> > +    "browser.startup.record": {
> > +    "layout.css.prefixes.webkit": {

> These both seem... excessive...

I would agree, though at least the former seems nightly/debug only ( https://dxr.mozilla.org/mozilla-central/source/js/xpconnect/loader/mozJSComponentLoader.cpp#467 ). Could obviously just convert those to a lazy pref though.

Comment 17

[Nicholas Nethercote [inactive]]

> I think a max of 40 for navigation
> and startup is quite high - 10 would be more reasonable, but we can file
> follow-ups to clamp down on this.

Let's consider how "expensive" a pref lookup is: it involves an XPConnect JS-to-C++ boundary traversal, and a hash table lookup. It's not *that* expensive :)  The difference between 40 and 10 lookups should be negligible. Unless you have profiling measurements that suggest otherwise, I wouldn't worry about optimizing prefs that aren't accessed 1000s of times in short periods.

Comment 18

[Johann Hofmann [:johannh]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=c183170bcbeedb82d5093171c773fef0a073f503

Comment 19

[Kris Maglione [:kmag]]

(In reply to Nicholas Nethercote [:njn] from comment #17)
> > I think a max of 40 for navigation
> > and startup is quite high - 10 would be more reasonable, but we can file
> > follow-ups to clamp down on this.
> 
> Let's consider how "expensive" a pref lookup is: it involves an XPConnect
> JS-to-C++ boundary traversal, and a hash table lookup. It's not *that*
> expensive :)  The difference between 40 and 10 lookups should be negligible.
> Unless you have profiling measurements that suggest otherwise, I wouldn't
> worry about optimizing prefs that aren't accessed 1000s of times in short
> periods.

I agree it's not the most expensive thing in the world, but it's certainly enough to add up.

From a quick micro-benchmark, the cost of a single Services.prefs.getStringPref call from a browser window, which is a usual case, is about 2,700ns when done from a tight loop. About 366ns of that is from the pref service. The rest is overhead.

In the best case, where the pref service reflector is in the same compartment, and accessible via a lexically scoped variable, the cost is about 1,940ns on a fast machine.

In the worst case, it gets much more expensive. It's pretty easy to wind up in situations where, for every call, we have to:

1) Walk the scope chain and do a slow property lookup on every scope up to the global.
2) Reach a cross-compartment wrapper for the Services object.
3) Enter the Services.jsm compartment, do a non-optimizable property lookup for "prefs" (since CCW lookups aren't cached).
4) Wrap the returned prefs object for the caller compartment, which means looking up an existing wrapper, failing to find it, creating an entirely new prefs service binding object for the calling compartment, storing that compartment in the wrapper map. This worst case happens fairly often (i.e., the first time we access the prefs service from a new compartment, and every time the existing wrapper is GCed).
5) Call the getStringPref method on the wrapper, which requires a slow tear-off look-up, followed by slow argument conversions, and a slow C++ virtual call.
6) Convert the returned string value to a JSString, which involves, among other things, a new string allocation.

All of this also has the side-effect of invaliding quite a lot of GC state.

Comment 20

[Kris Maglione [:kmag]]

(In reply to Kris Maglione [:kmag] (long backlog; ping on IRC if you're blocked) from comment #19)
> All of this also has the side-effect of invaliding quite a lot of GC state.

*JIT state

Comment 21

[Johann Hofmann [:johannh]]

Attachment: Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

These statistics will be used by browser tests to analyze frequently accessed
preferences so that we can recommend using preference observers instead.

Review commit: https://reviewboard.mozilla.org/r/224260/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/224260/

Comment 22

[Johann Hofmann [:johannh]]

Attachment: Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

Review commit: https://reviewboard.mozilla.org/r/224262/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/224262/

Comment 23

[Johann Hofmann [:johannh]]

Thanks Nicholas and Gijs for the feedback!

(In reply to Nicholas Nethercote [:njn] from comment #15)
> I strongly oppose having this in Nightly builds, because prefs is already a
> significant source of content process memory overhead and I am actively
> working on its memory usage.
> 
> But if it's debug builds only (as the comments in nsIPrefService.idl claim)
> that's probably ok.

I agree, let's make it debug only.

> @@ +729,5 @@
> >  
> >  static PLDHashTable* gHashTable;
> >  
> > +#if defined(NIGHTLY_BUILD) || defined(DEBUG)
> > +static nsDataHashtable<nsCStringHashKey, uint32_t>* gPrefAccessStatsTable;
> 
> To reduce memory usage, you can just add the count to the existing hash
> table. Add a uint32_t field to PrefEntry. (Don't add it to Pref; I have
> plans to make Pref `static` and that would interfere.)

That sounds like a good plan. I've changed my patch.

> This change means that you wouldn't record counts for lookups of
> non-existent prefs. Perhaps you could have a global count of those without
> recording their actual names? Probably depends how common such lookups are.

It seems that there are two prefs impacted by this (dom.ipc.multiOptOut and network.protocol-handler.external., which is a very interesting and possibly perf-sensitive case), but I'd rather move that to a follow-up to focus on actually landing this thing first.

(In reply to :Gijs from comment #16)
> Comment on attachment 8952025 [details] [diff] [review]
> Add a test for repeatedly called pref getters
> 
> The test/JS side of this looks OK to me. I think a max of 40 for navigation
> and startup is quite high - 10 would be more reasonable, but we can file
> follow-ups to clamp down on this. I'm intrigued you set it to 15 for opening
> 10 tabs. This would preclude items that the tabbrowser (or other consumers)
> look up for every tab, which is something we can probably optimize more
> easily.

I've set it to 10 now, it didn't make a big difference. In general we can just continue to adjust that pref value based on what we see as appropriate (as mentioned in some cases direct access is preferred to adding an observer, even if it happens semi-frequently).

Thanks!

Comment 24

[Johann Hofmann [:johannh]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=5e81bec122c96fe96d87d6958e8c2d91f0798fff

Comment 25

[Johann Hofmann [:johannh]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=2033ed918cdf5ddc52ac4c9d427345af3d82c4e9

Comment 26

[Brian Grinstead [:bgrins]]

(In reply to Johann Hofmann [:johannh] from comment #23)
> Thanks Nicholas and Gijs for the feedback!
> 
> (In reply to Nicholas Nethercote [:njn] from comment #15)
> > I strongly oppose having this in Nightly builds, because prefs is already a
> > significant source of content process memory overhead and I am actively
> > working on its memory usage.
> > 
> > But if it's debug builds only (as the comments in nsIPrefService.idl claim)
> > that's probably ok.

Something we added for tracking the XBL work that may also be useful here is the tier 3 browser-instrumentation taskcluster job, which runs the entire b-c suite in a single chunk on nightly jobs.

For example [0] which generates artifacts like [1] used to track XUL/XBL element usage. One nice thing about it is you can pull the data down from automation with a script like [2] to track changes over time.

I don't know if i'd make sense for this case, but if you think it might then there's an outline for how to add a new artifact for it here: https://bugzilla.mozilla.org/show_bug.cgi?id=1426509#c0.

[0]: https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=0f8f71b0b9d84e7732c07f841e395de516b31b66&filter-tier=1&filter-tier=2&filter-tier=3&selectedJob=165178743
[1]: https://taskcluster-artifacts.net/HV4cdCRLQg6jkjR4McwR6A/0/public/test_info/xulsummary.txt
[2]: https://github.com/bgrins/xbl-analysis/blob/adb3d6be249344b0adddc1c81898d51a647979bd/scripts/populate-cache.js#L72-L107

Comment 27

[Nicholas Nethercote [inactive]]

Comment on attachment 8955108 [details]
Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

https://reviewboard.mozilla.org/r/224260/#review230514

I'm not happy about the SpiderMonkey dependency (see below). Sorry I didn't think of that when I gave my first round of feedback.

::: modules/libpref/Preferences.cpp:722
(Diff revision 1)
>  class PrefEntry : public PLDHashEntryHdr
>  {
>  public:
>    Pref* mPref;  // Note: this is never null in a live entry.
> +#ifdef DEBUG
> +  uint32_t mLastAccessed;

I find this a very strange name for this field. It sounds like a time or an index, when it's actually a count.

How about mNumAccesses or mAccessCount?

::: modules/libpref/Preferences.cpp:723
(Diff revision 1)
>  {
>  public:
>    Pref* mPref;  // Note: this is never null in a live entry.
> +#ifdef DEBUG
> +  uint32_t mLastAccessed;
> +#endif

Put the new field before mPref, because that will result in better struct packing on 64-bit (because PLDHashEntryHdr has a single 4-byte field). And add a comment like "This field goes before mPref to minimize sizeof(PrefEntry) on 64-bit."

::: modules/libpref/Preferences.cpp:3359
(Diff revision 1)
>  
>  NS_IMETHODIMP
> +Preferences::GetStats(JSContext* aCx, JS::MutableHandleValue aVal)
> +{
> +#ifdef DEBUG
> +  JS::RootedObject obj(aCx, JS_NewPlainObject(aCx));

Hmm... this changes means that libpref now depends on SpiderMonkey. (There should be a `#include "jsapi.h"` added at the top.) I don't much like that, but I'm having trouble thinking how to else to structure this to avoid the dependency. Sorry.

::: modules/libpref/nsIPrefService.idl:116
(Diff revision 1)
>     * @note This method is intended for internal unit testing only!
>     */
>    void readUserPrefsFromFile(in nsIFile aFile);
> +
> +  /**
> +   * Usage statistics for performance tests. This currently

Nit: these comment lines are too short. Please wrap at 79 chars.

::: modules/libpref/nsIPrefService.idl:120
(Diff revision 1)
> +  /**
> +   * Usage statistics for performance tests. This currently
> +   * returns an object that maps preference names to how many
> +   * times the pref was accessed.
> +   * This is not implemented in non-debug builds and will
> +   * throw an error

Nit: '.' at end of sentence.

::: modules/libpref/nsIPrefService.idl:125
(Diff revision 1)
> +   * throw an error
> +   */
> +  [implicit_jscontext] readonly attribute jsval stats;
> +
> +  /**
> +   * Reset Usage statistics for performance tests.

Nit: these comment lines are too short. Please wrap at 79 chars.

::: modules/libpref/nsIPrefService.idl:127
(Diff revision 1)
> +  [implicit_jscontext] readonly attribute jsval stats;
> +
> +  /**
> +   * Reset Usage statistics for performance tests.
> +   * This is not implemented in non-debug builds and will
> +   * throw an error

Nit: '.' at end of sentence.

Comment 28

[Nicholas Nethercote [inactive]]

> Bug 1425613 - Part 1 - Record and expose pref access statistics in
> nsIPrefService in debug mode.
> 
> https://reviewboard.mozilla.org/r/224260/#review230514
> 
> I'm not happy about the SpiderMonkey dependency (see below).

kmag, do you have any ideas how this dependency could be avoided? (See comment 27 for details.)

Comment 29

[Kris Maglione [:kmag]]

(In reply to Nicholas Nethercote [:njn] from comment #28)
> > I'm not happy about the SpiderMonkey dependency (see below).
> 
> kmag, do you have any ideas how this dependency could be avoided? (See
> comment 27 for details.)

Yes. The easiest thing would probably be to create a [function] interface that gets a callback for every pref entry:

  Services.prefs.getStats((prefName, numCalls) => {
    ...;
  });

That would be a lot slower than the JSAPI approach, but as long as it's only used in tests, it shouldn't matter much.

Comment 30

[Florian Quèze [:florian]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

Clearing the review flag until the backend is ready. But thanks for working on this!

Comment 31

[Johann Hofmann [:johannh]]

Comment on attachment 8955108 [details]
Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224260/diff/1-2/

Comment 32

[Johann Hofmann [:johannh]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224262/diff/1-2/

Comment 33

[Johann Hofmann [:johannh]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=dc127a044c682e745db74a9c7869844235cce7a3

Comment 34

[Johann Hofmann [:johannh]]

Comment on attachment 8955108 [details]
Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

https://reviewboard.mozilla.org/r/224260/#review230514

> I find this a very strange name for this field. It sounds like a time or an index, when it's actually a count.
> 
> How about mNumAccesses or mAccessCount?

Gah, I had worked on another patch that had a mLastAccessed field at the same time when writing this. Must have become mixed up in my head. I hope the other one isn't called mAccessCount now :D

Comment 35

[Kris Maglione [:kmag]]

Comment on attachment 8955108 [details]
Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

https://reviewboard.mozilla.org/r/224260/#review231732

::: modules/libpref/nsIPrefStatsCallback.idl:16
(Diff revision 2)
> + */
> +[function, scriptable, uuid(c3f0cedc-e244-4316-b33a-80306a1c35a1)]
> +interface nsIPrefStatsCallback : nsISupports
> +{
> +  void visit(in string prefName, in unsigned long accessCount);
> +};

This doesn't need its own idl file.

Comment 36

[Johann Hofmann [:johannh]]

So this patch uses a callback/visitor/whatever interface to get the data. I'm not really happy with some of the names (the callback isn't really a callback) and I wonder whether it's possible to do this with even less fingerprint on actual release interfaces, but this is the best I can come up with...

Thanks for the advice :)

(In reply to Kris Maglione [:kmag] (long backlog; ping on IRC if you're blocked) from comment #35)
> Comment on attachment 8955108 [details]
> Bug 1425613 - Part 1 - Record and expose pref access statistics in
> nsIPrefService in debug mode.
> 
> https://reviewboard.mozilla.org/r/224260/#review231732
> 
> ::: modules/libpref/nsIPrefStatsCallback.idl:16
> (Diff revision 2)
> > + */
> > +[function, scriptable, uuid(c3f0cedc-e244-4316-b33a-80306a1c35a1)]
> > +interface nsIPrefStatsCallback : nsISupports
> > +{
> > +  void visit(in string prefName, in unsigned long accessCount);
> > +};
> 
> This doesn't need its own idl file.

Ah, right, I can move it. Thanks!

Comment 37

[Johann Hofmann [:johannh]]

Comment on attachment 8955108 [details]
Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224260/diff/2-3/

Comment 38

[Johann Hofmann [:johannh]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224262/diff/2-3/

Comment 39

[Johann Hofmann [:johannh]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=5a61b4a9a320880306501c1ca32cb1093f8fa248

Comment 40

[Nicholas Nethercote [inactive]]

Comment on attachment 8955108 [details]
Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

https://reviewboard.mozilla.org/r/224260/#review231880

This looks good. Thank you for your patience with the revisions :)

One final request: libpref is now formatted entirely with clang-format. Please run `./mach clang-format` to make sure the code you've changed/added has the right formatting. Thanks!

::: modules/libpref/Preferences.cpp:952
(Diff revision 3)
> +#ifdef DEBUG
> +  if (entry) {
> +    entry->mAccessCount += 1;
> +  }
> +#endif
>    return entry ? entry->mPref : nullptr;

I would rewrite this so `entry` is only tested once:
```
  if (!entry) {
    return nullptr;
  }

#ifdef DEBUG
  entry->mAccessCount += 1;
#endif
  return entry;
```

::: modules/libpref/Preferences.cpp:952
(Diff revision 3)
> +#ifdef DEBUG
> +  if (entry) {
> +    entry->mAccessCount += 1;
> +  }
> +#endif
>    return entry ? entry->mPref : nullptr;

I would rewrite this so `entry` is only tested once:

  if (!entry) {
    return nullptr;
  }

#ifdef DEBUG
  entry->mAccessCount += 1;
#endif
  return entry;

::: modules/libpref/Preferences.cpp:3399
(Diff revision 3)
>    prefBranch.forget(aRetVal);
>    return NS_OK;
>  }
>  
>  NS_IMETHODIMP
> +Preferences::ReadStats(nsIPrefStatsCallback* callback)

Nit: argument should be called `aCallback`.

Comment 41

[Nicholas Nethercote [inactive]]

> I would rewrite this so `entry` is only tested once:

Hmm, I'm not sure why MozReview duplicated that comment...

Comment 42

[Johann Hofmann [:johannh]]

Comment on attachment 8955108 [details]
Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224260/diff/3-4/

Comment 43

[Johann Hofmann [:johannh]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224262/diff/3-4/

Comment 44

[Johann Hofmann [:johannh]]

Thanks!

Comment 45

[Johann Hofmann [:johannh]]

Comment on attachment 8955108 [details]
Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224260/diff/4-5/

Comment 46

[Johann Hofmann [:johannh]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224262/diff/4-5/

Comment 47

[Florian Quèze [:florian]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

https://reviewboard.mozilla.org/r/224262/#review232358

My comments are mostly trivial, but I would like to have another look at the final version.

::: browser/base/content/test/performance/browser_preferences_usage.js:6
(Diff revision 5)
> +/* Any copyright is dedicated to the Public Domain.
> +   http://creativecommons.org/publicdomain/zero/1.0/ */
> +
> +/**
> + * A test that checks whether any preference getter was called more often
> + * than the *max* parameter. You can also pass in a *whitelist*, which

"You can also pass in a *whitelist*" sounds like the whitelist is optional. The code will throw if whitelist isn't an object.

::: browser/base/content/test/performance/browser_preferences_usage.js:7
(Diff revision 5)
> +   http://creativecommons.org/publicdomain/zero/1.0/ */
> +
> +/**
> + * A test that checks whether any preference getter was called more often
> + * than the *max* parameter. You can also pass in a *whitelist*, which
> + * is an array with object elements that look like the following:

This says it's an array, but your actual calls pass an object.

::: browser/base/content/test/performance/browser_preferences_usage.js:16
(Diff revision 5)
> + *                 been called (to avoid keeping around dead items)
> + *   max: [Number] the maximum amount of times this should have
> + *                 been called (to avoid this creeping up further)
> + * }
> + */
> +function checkPrefGetters(whitelist, max, stats) {

I think this function could do with a nicer documenting comment, specifying clearly each parameter.

Also, I would be tempted to reorder the parameters to make stats the first one, whitelist the second parameter (not sure if giving it a default value of {} would make sense) and max the last parameter with a large default value (40).

::: browser/base/content/test/performance/browser_preferences_usage.js:33
(Diff revision 5)
> +          `Whitelist item ${pref} should be accessed at least ${whitelistItem.min} times.`);
> +      }
> +      if (whitelistItem.max) {
> +        Assert.lessOrEqual(count, whitelistItem.max,
> +          `Whitelist item ${pref} should be accessed at most ${whitelistItem.max} times.`);
> +      }

If there's a whitelist entry without min and without max, we just ignore it silently. Shouldn't we at least have an info message saying which pref was accessed how many times?

::: browser/base/content/test/performance/browser_preferences_usage.js:34
(Diff revision 5)
> +      }
> +      if (whitelistItem.max) {
> +        Assert.lessOrEqual(count, whitelistItem.max,
> +          `Whitelist item ${pref} should be accessed at most ${whitelistItem.max} times.`);
> +      }
> +      delete whitelist[pref];

I dislike that this destroys the provided whitelist object. A test attempting to use twice the same whitelist will have a bad surprise.

::: browser/base/content/test/performance/browser_preferences_usage.js:57
(Diff revision 5)
> +add_task(async function debug_only() {
> +  ok(AppConstants.DEBUG, "You need to run this test on a debug build.");
> +});
> +
> +// Just checks how many prefs were accessed during startup. This
> +// is guaranteed by our test running in its own sub-directory (in

"This is guaranteed by our test running in its own sub-directory" seems a left over from the previous version that didn't use startupRecorder.

::: browser/base/content/test/performance/browser_preferences_usage.js:101
(Diff revision 5)
> +
> +  let startupRecorder = Cc["@mozilla.org/test/startuprecorder;1"].getService().wrappedJSObject;
> +  await startupRecorder.done;
> +
> +  // XXX: In verify tests, prefStats becomes undefined at some point. That isn't really
> +  // a problem since we need to assert startup only once, but, why?

Would be good to figure this out.

::: browser/base/content/test/performance/browser_preferences_usage.js:164
(Diff revision 5)
> +  };
> +
> +  Services.prefs.resetStats();
> +
> +  let tabs = [];
> +  for (let i = 0; i < 10; i++) {

nit: while (tabs.length < 10) would be clearer.

::: browser/base/content/test/performance/browser_preferences_usage.js:175
(Diff revision 5)
> +  }
> +
> +  checkPrefGetters(whitelist, max, getPreferenceStats());
> +});
> +
> +// This navigates to 50 sites and checks pref getters.

This seems to be mostly checking switching the security UI back and forth between https and http.

Comment 48

[Johann Hofmann [:johannh]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

https://reviewboard.mozilla.org/r/224262/#review232358

> Would be good to figure this out.

Ok this might have just been me being a doofus and using startupRecorder.prefStats instead of startupRecorder.data.prefStats (which with the old system was replaced by Services.prefs.stats if one passed undefined). I'm still not entirely certain about some of the details here, but it doesn't seem to happen on verify anymore (on my machine) and that makes me not want to investigate more.

> This seems to be mostly checking switching the security UI back and forth between https and http.

Yeah, that check isn't really great. We can always fix them up later, I'm thinking? :)

Comment 49

[Johann Hofmann [:johannh]]

Comment on attachment 8955108 [details]
Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224260/diff/5-6/

Comment 50

[Johann Hofmann [:johannh]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224262/diff/5-6/

Comment 51

[Johann Hofmann [:johannh]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=56de9d7cd323f9d6cd5b5b1339baab50cbf2d386

Comment 52

[Johann Hofmann [:johannh]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224262/diff/6-7/

Comment 53

[Johann Hofmann [:johannh]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=573082ff60b27aaf2188251d53b4ce1421c7ea37

Comment 54

[Florian Quèze [:florian]]

I would like TV jobs to be included in these try runs (-u test-verify-e10s)

Comment 55

[Johann Hofmann [:johannh]]

(In reply to Florian Quèze [:florian] from comment #54)
> I would like TV jobs to be included in these try runs (-u test-verify-e10s)

I agree. I can't figure out how to trigger them with ./mach try, so I'll manually add those once I have an all green try run (just need to tweak some numbers).

Comment 56

[Marco Castelluccio [:marco]]

(In reply to Johann Hofmann [:johannh] from comment #55)
> (In reply to Florian Quèze [:florian] from comment #54)
> > I would like TV jobs to be included in these try runs (-u test-verify-e10s)
> 
> I agree. I can't figure out how to trigger them with ./mach try, so I'll
> manually add those once I have an all green try run (just need to tweak some
> numbers).

Try with "./mach try fuzzy", you should find them in the list.

Comment 57

[Florian Quèze [:florian]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

https://reviewboard.mozilla.org/r/224262/#review233892

::: browser/base/content/test/performance/browser_preferences_usage.js:77
(Diff revisions 5 - 7)
>  add_task(async function startup() {
>    let max = 40;
>  
>    let whitelist = {
>      "browser.startup.record": {
> -      min: 300,
> +      min: 250,

Your latest try run suggests lowering that value to 200.

Comment 58

[Johann Hofmann [:johannh]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=88899257d89b06df256af16d886f3a2fbd50784b

Comment 59

[Johann Hofmann [:johannh]]

Comment on attachment 8955108 [details]
Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224260/diff/6-7/

Comment 60

[Johann Hofmann [:johannh]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224262/diff/7-8/

Comment 61

[Johann Hofmann [:johannh]]

Comment on attachment 8955108 [details]
Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224260/diff/7-8/

Comment 62

[Johann Hofmann [:johannh]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224262/diff/8-9/

Comment 63

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4939d44bcd0a
Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode. r=njn
https://hg.mozilla.org/integration/autoland/rev/6426e089e5c5
Part 2 - Add a test for repeatedly called pref getters. r=florian

Comment 64

[Andreea Pavel [:apavel]]

Backed out for browser chrome failures at automation.py

Push that caused the failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=6426e089e5c548dc1c75bc055792d85fe89573ea

Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=168648959&repo=autoland&lineNumber=2201

Backout: https://hg.mozilla.org/integration/autoland/rev/b36868e9d272ad4ed7c17201ebca364c53563214

Comment 65

[Johann Hofmann [:johannh]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=cfb8c472b1688ee899632e445375c786471010a9

Comment 66

[Johann Hofmann [:johannh]]

Comment on attachment 8955108 [details]
Bug 1425613 - Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224260/diff/8-9/

Comment 67

[Johann Hofmann [:johannh]]

Comment on attachment 8955109 [details]
Bug 1425613 - Part 2 - Add a test for repeatedly called pref getters.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/224262/diff/9-10/

Comment 68

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/7d8cb15237ba
Part 1 - Record and expose pref access statistics in nsIPrefService in debug mode. r=njn
https://hg.mozilla.org/integration/autoland/rev/4e6161888d13
Part 2 - Add a test for repeatedly called pref getters. r=florian

Comment 69

[Arthur Iakab [arthur_iakab]]

https://hg.mozilla.org/mozilla-central/rev/7d8cb15237ba
https://hg.mozilla.org/mozilla-central/rev/4e6161888d13