1551313 - Add profiler markers for preference reads

Status: RESOLVED FIXED

(Core :: Preferences: Backend, enhancement, P3)

Description

[Randell Jesup [:jesup] (needinfo me)]

When starting Fenix on a Motorola G5, we noticed that the WatchdogManager was taking a lot of time to start early in the process, and most of that was in starting the prefs service (and parsing the preferences). About 2% of startup captures on the Main Thread were spent there.

https://irccloud.mozilla.com/file/pwTR5BG0/report.html , click on flamegraphs and the pie chart, and look at the top thread listed "27838 (Gecko)", and look above (left side) of ScopedXPCOMStartup(). If you click on WatchdogManager::WatchdogManager() you'll zoom in on it.

Per myk, we could avoid reading default prefs by compiling them into the executable, which could avoid parsing probably 90% of the prefs. Doing it off-main-thread in parallel to other startup work might help, though once something needs a pref value it's going to block on that.

LMDB might also help by replacing the loading/parsing with actual database operations, but that's a bigger/more-expensive change.

Comment 1

[Olli Pettay [:smaug][[e-mail]]]

We do have StaticPrefList because of this. We should move more (all?) default prefs there.

Comment 2

[Jim Porter (:squib)]

(In reply to Olli Pettay [:smaug] from comment #1)

We do have StaticPrefList because of this. We should move more (all?) default prefs there.

This requires reading the prefs differently, right? (e.g. StaticPrefs::dom_animations_api_core_enabled() rather than using the prefs service as normal.) Are you/Randell thinking of moving away from the prefs service API calls entirely (at least for C++)?

Comment 3

[Randell Jesup [:jesup] (needinfo me)]

We do have StaticPrefList because of this. We should move more (all?) default prefs there.

This requires reading the prefs differently, right? (e.g. StaticPrefs::dom_animations_api_core_enabled() rather than using the prefs service as normal.) Are you/Randell thinking of moving away from the prefs service API calls entirely (at least for C++)?

StaticPrefs is one way, but even using the prefs service with defaults (instead of defaults living in or duplicated in all.js) would help I think. I.e. nothing to read and parse at startup unless a pref has a non-default value.

Comment 4

[Jim Porter (:squib)]

Attachment: Add profile markers for pref access

Here's a patch that adds profiler markers for all the times Firefox gets a pref. This should be useful for determining what prefs are actually needed during startup, and if the set is fairly small, we might be able to handle those specially (or, if the set is very large, we'll know that we need a more-general solution).

I'm not sure if this feature makes sense to land in m-c or if it's so special-purpose that we should leave it as a patch people can apply locally. Maybe just a build-time flag?

Needinfo'ing Will and Nick since they mentioned they might be interested in something like this.

Comment 5

[Will Hawkins]

Thanks, Jim! This is very close to what Nick and I are looking for in order to determine which preferences are the most-often accessed during the course of a run. In order to learn more about the build system, I am going to extend your work (slightly) to add in a configure flag so that this code will be conditionally included at compile time. Not that you'll want to take the code, but it was something you suggested and something I want to learn how to do!

Thanks again, Jim!

Comment 6

[Olli Pettay [:smaug][[e-mail]]]

My gut feeling is that having markers enabled by default would be too noisy.
(and TimeStamp::Now() usage would possibly show up in the profiles)

Comment 7

[Nick Alexander :nalexander [he/him]]

(In reply to Will Hawkins from comment #5)

Thanks, Jim! This is very close to what Nick and I are looking for in order to determine which preferences are the most-often accessed during the course of a run. In order to learn more about the build system, I am going to extend your work (slightly) to add in a configure flag so that this code will be conditionally included at compile time. Not that you'll want to take the code, but it was something you suggested and something I want to learn how to do!

Neat! If there's an existing "enable debug" flag in libpref, maybe just throw it behind that? But if you want to learn about simple build time flags, follow examples like https://searchfox.org/mozilla-central/rev/4fbcfe6fecf75d7b828fbebda79a31385f7eab5f/toolkit/moz.configure#43-58. You won't need the set_define; instead, in the relevant moz.build file, set the local DEFINES like https://searchfox.org/mozilla-central/rev/4fbcfe6fecf75d7b828fbebda79a31385f7eab5f/browser/app/moz.build#62-63.

Comment 8

[Will Hawkins]

Attachment: Bug 1551313: Insert profiler markers when preferences are accessed.

I extended squib's awesome patch so that the markers are inserted only when configured at build time and contain structured data. I'd love feedback!

Comment 9

[Jim Porter (:squib)]

I just took a brief look, but this all seems right. Thanks for extending my patch! There might be some diagnostic functions for prefs that already do similar stuff to the functions you added, though I'm not an expert on that part of the codebase.

One possible concern is that the reason I used a TextMarker in my patch was to avoid having to add UI support for a new marker kind in profiler.firefox.com. However, if you're planning to land this in m-c and have a corresponding UI patch for it, then this is the right way to go about it (as far as I know, at least). If we do want to land this, it's probably worth making a new bug so the stuff in comments 0-3 isn't lost.

Comment 10

[Will Hawkins]

Attachment: Bug 1551313: Insert profiler markers when preferences are accessed.

Comment 11

[Will Hawkins]

Support for the front end is submitted in a PR: https://github.com/firefox-devtools/profiler/pull/2178

Also, you can see how it looks here: https://pasteboard.co/IqhHGkr.png

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/7fd9b797a83e
Insert profiler markers when preferences are accessed. r=squib,gregtatum

Comment 13

[Cristian Brindusan [:cbrindusan]]

Backed out 1 changesets (bug 1551313) for build bustages at ProfilerMarkerPayload.cpp.

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

Push that started the failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception&revision=7fd9b797a83ea0e87994e0546b92b5c033385f7a&selectedJob=263053965

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=263053965&repo=autoland&lineNumber=29182

Comment 14

[Narcis Beleuzu [:NarcisB]]

There were also bc failures on browser_test_feature_preferencereads.js
Log link: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=263058945&repo=autoland&lineNumber=6683

Comment 15

[Will Hawkins]

(In reply to Narcis Beleuzu [:NarcisB] from comment #14)

There were also bc failures on browser_test_feature_preferencereads.js
Log link: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=263058945&repo=autoland&lineNumber=6683

This is almost surely because it failed to compile and only with the patches applied in their entirety would this test pass.

Thanks!

Comment 16

[Narcis Beleuzu [:NarcisB]]

I tried to import all the patches but received:
applying https://bug1551313.bmoattachments.org/attachment.cgi?id=9080235
patching file js/public/ProfilingCategory.h
Hunk #1 FAILED at 69
1 out of 1 hunks FAILED -- saving rejects to file js/public/ProfilingCategory.h.rej
patching file modules/libpref/Preferences.cpp
Hunk #1 FAILED at 11
Hunk #3 FAILED at 4481

Please check this issue and also please use "depends on" next time a patch depends on another.

Thank you!

Comment 17

[Will Hawkins]

(In reply to Narcis Beleuzu [:NarcisB] from comment #16)

I tried to import all the patches but received:
applying https://bug1551313.bmoattachments.org/attachment.cgi?id=9080235
patching file js/public/ProfilingCategory.h
Hunk #1 FAILED at 69
1 out of 1 hunks FAILED -- saving rejects to file js/public/ProfilingCategory.h.rej
patching file modules/libpref/Preferences.cpp
Hunk #1 FAILED at 11
Hunk #3 FAILED at 4481

Please check this issue and also please use "depends on" next time a patch depends on another.

Thank you!

Something is amiss. I rebased this against central before trying to land. It should not be failing to apply.

Comment 18

[Will Hawkins]

(In reply to Narcis Beleuzu [:NarcisB] from comment #16)

I tried to import all the patches but received:
applying https://bug1551313.bmoattachments.org/attachment.cgi?id=9080235
patching file js/public/ProfilingCategory.h
Hunk #1 FAILED at 69
1 out of 1 hunks FAILED -- saving rejects to file js/public/ProfilingCategory.h.rej
patching file modules/libpref/Preferences.cpp
Hunk #1 FAILED at 11
Hunk #3 FAILED at 4481

Please check this issue and also please use "depends on" next time a patch depends on another.

Thank you!

Were you trying to apply the patch from phabricator or the one(s) attached? I think that's the problem here.

Comment 19

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/243d7178baf8
Insert profiler markers when preferences are accessed. r=squib,gregtatum

Comment 20

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/243d7178baf8

Comment 21

[BugBot [:suhaib / :marco/ :calixte]]

Since the status are different for nightly and release, what's the status for beta?
For more information, please visit auto_nag documentation.

Comment 22

[Nicholas Nethercote [inactive]]

It would have been nice to have a libpref peer review this. They could have pointed out that there is already stats collection built into libpref, accessible via nsIPrefService::readStats(). Having two stats systems is sub-optimal.

Comment 23

[Olli Pettay [:smaug][[e-mail]]]

I wonder why https://searchfox.org/mozilla-central/rev/e3fc8f8970491aef14d3212b2d052942f4d29818/tools/profiler/tests/browser/browser_test_feature_preferencereads.js#38,58 is needed and why is that guaranteed to work always

Comment 24

[Markus Stange [:mstange]]

I'm renaming this bug to reflect what landed here. The patch had nothing to with reducing CPU use during initialization of the preferences service.

The real issue that the profiles showed is being fixed in bug 1619032.