1554395 - StartupCache takes a very long time to write out cache after browser startup

Status: NEW

(Core :: XPCOM, defect)

Description

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

In bug 1554183 I have a patch to put Log messages into the StartupCache (since it didn't seem to be working).

I see it (eventually) trying to write the data, but when the font code asks for a cache on the next startup, it doesn't get one. (I removed the --purgecaches which geckoview does then it's a android debuggable build) I have not tried fennec or fenix.

Note that it may be many minutes before it tries to write the cache, since it has a 60s timer that's reset whenever anything tries to add to the cache. (comment says 10, but it's 60, and has been since it was initially added in 2011)

From 1554183: "to get it to write, it has to be idle for 60s continuously (or more). I did get it to write finally, and then it didn't find a cache on restart even with purgecaches removed.
Passing the ball to someone.... looks like a startup cache issue."

There's also a patch there to add more fontInfoLog log messages to narrow in on cache writing

Comment 1

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

Ok, it is writing. But it can take a very long time, and if gecko is killed (quite possible - this is Android), it won't write. I don't know what happens if it's busy.

See the log I'll attach - it took 2.5 minutes to write the font data to the cache. There's an odd pattern - the jsloader//.jsm files get hit in bursts every 30 seconds, several at a time (resetting the 60s write timer), until apparently it runs out of them and finally writes the StartupCache 2.5 minutes after the first data was put in it. Why are those JSMs taking so long to populate the buffer?

Note: the browser was 100% idle here. Sitting after started with an intent, waiting for a URL. For a good part of it the display was off (after about 1 or 2 minutes).

Who can look into the "why 30 groups of JSMs"? (snorp, any idea who would know?)

I think the 60s timeout here is a bit of a problem.... In theory, this should only be needed on OS updates (font data) or browser updates (JSM changes), I think - at least the data I see being stored currently.

Nathan - who is responsible for startupcache? Thoughts on the right way to do this?

Comment 2

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

Attachment: log1

Comment 3

[Alex Thayer [:alexical] (she/her)]

FWIW in bug 1550108 I'm working on compressing the StartupCache's archive with lz4, which in my testing is cheaper on CPU to compress for the same ratio. So that may make it slightly more palatable to write it on a shorter timer.

Comment 4

[Chris Pearce [:cpearce (Not reading bugmail)]]

(In reply to Randell Jesup [:jesup] (needinfo me) from comment #1)

Ok, it is writing. But it can take a very long time, and if gecko is killed (quite possible - this is Android), it won't write.

I added ProcessLifecycleObservers to GV in bug 1540573, maybe we need to flush the startup cache inside a one of these observer notifications, in order to prevent us failing to write the cache when we're killed by Android?

Comment 5

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

That's a worthwhile consideration/option, though a fair bit of plumbing from Java to C++ would need to happen. And we also need to address flushing the cache better on desktop too. We'd need to listen for onStop or maybe onSaveInstanceState() (which isn't LifeCycle...). I'm unsure how this interacts with the OS nuking things under memory pressure/etc, though I'm guessing they work in those cases.

Comment 6

[James Willcox (:snorp) ([e-mail]) (he/him)]

I think jesup has this fixed up now?

I agree with comment #4, though, that we probably want to flush any pending startup cache writes when we're backgrounded.

Comment 7

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

No, I fixed the fontnamecache not even trying to save to the StartupCache unless it saw a shutdown notification. The resetting-60s-timer for StartupCache is still there.

Comment 8

[James Willcox (:snorp) ([e-mail]) (he/him)]

(In reply to Randell Jesup [:jesup] (needinfo me) from comment #7)

No, I fixed the fontnamecache not even trying to save to the StartupCache unless it saw a shutdown notification. The resetting-60s-timer for StartupCache is still there.

I see. In that case, yes, let's flush the cache when backgrounding. We should make GeckoView send application-background and application-foreground events appropriately, then startup cache can just listen to that.

Comment 9

[Nathan Froyd [:froydnj]]

kmag is responsible for startupcache.

Comment 10

[Jens Stutte [:jstutte]]

Renewing the ni? as it has probably gone unobserved. I do not know, if this is still an issue.

Comment 11

[Kris Maglione [:kmag]]

I don't have very much to do with startupcache. I do own the related but mostly separate ScriptPreloader. I may be able to look at it if it's still causing trouble, though

Comment 12

[Jens Stutte [:jstutte]]

Randell, is this still an issue ?

Comment 13

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

yes, still an issue: static uint8_t STARTUP_CACHE_WRITE_TIMEOUT = 60;
(sorry for the delay)