1619032 - Preferences initialization spends 100ms in NotifyCallbacks on a Moto G5

Status: RESOLVED FIXED

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

Description

[Markus Stange [:mstange]]

Android startup profile: https://perfht.ml/2PwxlmY

Of the 150ms spent in Preferences::InitInitialObjects, 100ms are spent in NotifyCallbacks, 85ms of that in CallbackNode::Matches. I can't see it clearly in the profile but I think that we don't actually spend any time at all in the actual notification callback functions - only in checking who needs to be notified.

Is there a way to speed up this matching process? If we're matching up N prefs with M listeners, can we find a way to organize the listeners so that we don't have to check N x M pairs?

Comment 1

[Markus Stange [:mstange]]

I'm looking into this a bit.

Comment 2

[Markus Stange [:mstange]]

Attachment: diagnostic patch with profiler markers

Logs: https://perfht.ml/3cIYSLR (macOS non-omnijar), https://perfht.ml/2Q0mBND (Android omnijar)

The callbacks we're iterating over are the callbacks installed for "mirror: always" static prefs. There are just over 1000 of them. (1087 in my local macOS build, 1093 in my Android build.)

Preferences::InitInitialObjects calls, in this order:

1. StaticPrefs::InitAll - this sets all static prefs and registers listeners for "mirror: always" prefs.
2. openPrefFile + pref_LoadPrefsInDir, or pref_ReadPrefFromJar + pref_ReadDefaultPrefs in the omnijar case.

Every pref that's set in step 2 is checked against all 1000 staticpref callbacks. And even during step 1, the Nth "always" static pref is checked against (N - 1) callbacks for the previous "always" static prefs.

On Android, I'm getting the following numbers (by executing filteredMarkers.length in the web console in the profiler after zooming in on various ranges):

1. 116 "never"/"once" static prefs
2. 1093 "always" static prefs
3. 1654 prefs from jar
4. 363 default prefs

So during initialization, we perform the following number of callback checks:
(1093 * 1092) / 2 + (1654 + 363) * 1093 = 2801359

I think we can bring this cost down to zero by installing the mirror listeners for the "always" static prefs after step 2.

Comment 3

[Markus Stange [:mstange]]

Before: https://perfht.ml/2TTUPn4 After: https://perfht.ml/2VYp3YN
From 162ms spent in Preferences::InitInitialObjects down to 22ms. That's a 140ms speedup!

Comment 4

[Markus Stange [:mstange]]

Attachment: Bug 1619032 - Register 'mirror: always' StaticPref callbacks after pref values have been read. r=njn

This speeds up startup by 140ms on a Moto G5 Android device because it avoids almost 3 million calls to CallbackNode::Matches.

The patch contains the following changes:

• InitAlwaysPref no longer calls AddMirrorCallback.
• InitAlwaysPref loses its aIsParent and aIsStartup arguments and is now only called in the parent.
• InitAll now only does work in the parent, and doesn't care if it's called for startup.
• There's a new function, StaticPrefs::StartObservingAlwaysPrefs() which gets called after all prefs have been loaded on startup.
• The new function calls AddMirror rather than AddMirrorCallback so that any pref values from the data files get picked up into the mirrors.
• AddMirror requires a fallback argument. I used the current value of the mirror as the fallback value.

Comment 5

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

The priority flag is not set for this bug.
:njn, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/37f9e7220df0
Register 'mirror: always' StaticPref callbacks after pref values have been read. r=njn

Comment 7

[Oana Pop-Rus]

https://hg.mozilla.org/mozilla-central/rev/37f9e7220df0

Comment 8

[Markus Stange [:mstange]]

Talos improvement (originally posted to bug 1557570):

== Change summary for alert #25435 (as of Thu, 19 Mar 2020 04:12:16 GMT) ==

Improvements:

7% ts_paint linux64-shippable opt e10s stylo 199.92 -> 186.50
7% ts_paint_webext linux64-shippable opt e10s stylo 199.33 -> 186.33
5% ts_paint_webext linux64-shippable-qr opt e10s stylo 279.88 -> 267.00
4% ts_paint windows7-32-shippable opt e10s stylo 320.21 -> 307.92
4% ts_paint windows7-32-shippable opt e10s stylo 319.75 -> 308.08

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=25435