1623518 - [meta] Script cache information from the content process is never written to disk in GeckoView (10-20ms startup penalty for uncached script loading)

Status: NEW

(GeckoView :: Sandboxing, defect, P3)

Description

[Markus Stange [:mstange]]

Profile: https://perfht.ml/2QsgbHE

We're hitting "script emit" during startup for the following scripts:

Parent process:

• ExtensionChild.jsm

Content process:

• ExtensionProcessScript.jsm
• XPCOMUtils.jsm
• GeckoViewUtils.jsm
• Services.jsm
• AppConstants.jsm

We need these scripts on every startup and they're on the critical app link startup path. My understanding is the following: For scripts that are in the startup cache, we don't see "script emit" profiler labels. So are these scripts not in the startup cache?

We should make sure they get into the startup cache.

Comment 1

[Markus Stange [:mstange]]

I expect this to save about 15-30ms during content process startup on a Moto G5.

Comment 2

[Markus Stange [:mstange]]

Another profile: https://perfht.ml/38WyACE

Comment 3

[Brendan Dahl [:bdahl]]

Just to confirm before I dig into this some more. Are you waiting around ~1min on the first run of gecko before killing and restarting? The startup cache isn't written until this time.

Comment 4

[Markus Stange [:mstange]]

Yes, I have waited for that long. I even have two profiles to compare, one before startup cache initialization (grabbed just after I installed an update), and one after. The two show drastically different amounts of times spent in "script emit".
Before: https://perfht.ml/2WtruCU
After: https://perfht.ml/3d7EhRs

And, importantly, the latter still shows some time spent in "script emit" in the content process under ChromeUtils::Import resource://gre/modules/ExtensionProcessScript.jsm. (These profiles were taken with a 5ms interval so they have fewer samples with script emit than the ones in comment 0 and comment 2 which used a 0.4ms interval.)
Ignore the "script emit" under JS::InitSelfHostedCode - that's bug 1618391.

Comment 5

[Jan Henning [:JanH]]

I added the "browser-idle-startup-tasks-finished" notification (which the startup cache depends on) in bug 1496684 mainly as a side effect of fixing a GeckoView issue for Fennec, so there is definitively some scope for further tuning the precise moment we're going to fire it (or conversely when we're loading the other modules).

Comment 6

[Markus Stange [:mstange]]

I see. The profile shows "browser-idle-startup-tasks-finished" being sent long before ExtensionChild.jsm is used in the parent process: https://bit.ly/2WOJJDj / https://bit.ly/3biauE2
So that explains why ExtensionChild.jsm is not in the startup cache for the parent process.

About child processes, the comments in the code have the following to say:

// - For content processes, opening and writing the cache file is handled in the
// parent process. The first content process of each type sends back the data
// for scripts that were loaded in early startup, and the parent merges them
// and writes them to a cache file.

The content process sends back this data when it fires the "document-element-inserted" observer notification:

// In the child process, we need to freeze the script cache before any
// untrusted code has been executed. The insertion of the first DOM
// document element may sometimes be earlier than is ideal, but at
// least it should always be safe.
mContentStartupFinishedTopic.AssignLiteral(DOC_ELEM_INSERTED_TOPIC);

In the profile, the content process fires "document-element-inserted" long after it uses e.g. ExtensionProcessScript.jsm: https://bit.ly/3dpYa6F / https://bit.ly/3bp4R6V . So for the content process, the observer notification timing does not explain why these JSM files are not getting into the startup cache.

Comment 7

[Markus Stange [:mstange]]

Hmm, from reading the code, it looks like the parent process writes out child scripts at the same time as it writes out parent process scripts. That means that if the child process sends its data after the parent process has already written its data, the child data will never get written. Kmag, does that match your understanding?

Comment 8

[Markus Stange [:mstange]]

Yeah, here are profiles from Firefox Preview Nightly that include the "SaveScripts" thread: https://bit.ly/2JkdgMR (first start after update), https://bit.ly/2Uj4rt8 (second start after update).
You can see that the cache is written long before the content process sends up its data, and then no further writes are issued in the parent process (no second SaveScripts thread is started).

Comment 9

[Brendan Dahl [:bdahl]]

It looks like there are actually two parts to this bug:

1. Scripts are running before the ScriptPreloader is initialized in the content process
2. We need to delay when the ScriptPreloader stops marking script to cache.

For #1, I've filed bug 1632682. For #2, there's a bug already bug 1468673

Comment 10

[Brendan Dahl [:bdahl]]

I left a comment in the blocking bug, but in summary I didn't see any perf changes for geckoview when fixing this. It still may be nice to fix that bug at some point, but there was one desktop talos regression that may be troublesome.

Comment 11

[Kris Maglione [:kmag]]

For what it's worth, I got rid of ContentProcessSingleton.jsm in bug 1645862, which according to bug 1632682 was the main thing running before the preloader was initialized. Unfortunately, there are still some other JS things observing app-startup in content processes, including TelemetryControllerContent.jsm (which is a stripped-down version of what used to load from ContentProcessSingleton) and GeckoViewStartup.jsm.

I think both of those can probably be trivially changed to use a new hook that runs later in content process startup. Given the amount of code those modules entrain, I think that would be an important step in getting a significant improvement out of the preloader cache in content processes.

But we'd also need to actually write scripts loaded by the content process to the preloader cache, or they obviously wouldn't be available anyway. So fixing the cache write would be a prerequisite for testing the performance improvement of that change.

Comment 12

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

Attachment: cold-view--which-scripts-cached.txt

To summarize my understanding, the issue is that the script cache slow loads some scripts which we expect to be cached. There are two root causes (which :bdahl mentioned in comment 9):

1. Some scripts in the child process run before the ScriptPreloader is ready to cache them
2. The ScriptPreloader in the child process returns its cached scripts to the parent process before all start up scripts have finished running

You can see the timing in the markers in this profile from a recent fenix Nightly: https://share.firefox.dev/34oRUMh You can roughly see IPCIn — PContent::Msg_PScriptCacheConstructor for when the ScriptPreloader is init and IPCOut — PScriptCache::Msg___delete__ for when the child process sends its cache to the parent. The GeckoViewStartup.jsm script occurs during init and is not cached (bug 1; see attachment for which scripts are cached). ExtensionProcessScript.jsm occurs after init and is cached. ContentMetaChild.jsm occurs just before ___delete__ and is not cached (bug 2).

I was able to identify which scripts are cached and which aren't by parsing the JSComponentLoader logs with this script. I attached the output of a typical COLD VIEW. The pattern shown generally holds – ~18 child process scripts cached (the rest are slow loaded) and all the parent process scripts cached – for both COLD MAIN and COLD VIEW if there is a page load.

---

In my investigation, I found one more issue: if the previous session didn't load any pages, the next session will have to slow load all of the scripts. This seems likely to happen when the previous process was started from a background job. I filed Bug 1753336.

Comment 13

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

Attachment: cold-view-which-scripts-cached.txt

(added parent process results to attachment)

Comment 14

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

I discovered that some scripts that are loaded from cache in the parent are unexpectedly slow loaded in the child process (7 of 12) so I filed bug 1755533.

Comment 15

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

The ScriptPreloader in the child process returns its cached scripts to the parent process before all start up scripts have finished running

I suspect this doesn't have a significant impact on start up (yet?) because:

1. From this cold start profile to a simple page (example.com), I believe the network request is blocked on jank in the main thread such that the uncached scripts in the child process are not the bottleneck: https://share.firefox.dev/3oTFqno
2. I pushed a patch that removes the uncached scripts in the child process besides ConduitsChild.jsm (~20ms worth) and ran it through perfherder for cold page load. Some pages load faster and some slower

So maybe just bug 1632682 (scripts are loaded before the preloader) is the impactful work of this meta bug.

Comment 16

[Chris Peterson [:cpeterson]]

Moving content process management bugs to the new GeckoView::Sandboxing component.