1664025 - Fenix applink startup delayed ~200-300ms (Pixel 2) in checkForChanges() (XPIProvider.jsm)

Status: RESOLVED INVALID

(Toolkit :: Add-ons Manager, task)

Description

[Andrew Creskey [:acreskey]]

We track Fenix applink startup in this test.

(This measures time from process start to navigationStart for a test url).

We noticed that when using existing user profiles (as opposed to new profiles), startup is consistently ~200 to 300ms slower (Pixel 2).

From profiling this, it looks like the difference comes from time spent in checkForChanges() via processFileChanges() in the XPIDatabase.
https://share.firefox.dev/2Ra0hBt

For comparison, here is an gecko-profile using a new user profile:
https://share.firefox.dev/3k6oS6N

If XPIDatabse checkForChanges() is slowing down startup, would it be possible to move this out of the critical path for an android applink startup scenario?

Are there other alternatives?

Comment 1

[Andrew Creskey [:acreskey]]

Also, should I expect to see this spent in checkForChanges() on every startup?

Comment 2

[Andrew Swan [:aswan]]

processFileChanges() is generally not called on every startup. One of the conditions here must have been true: https://searchfox.org/mozilla-central/rev/8a0745cd346f0cfb89ae71690babbf7bff706113/toolkit/mozapps/extensions/internal/XPIProvider.jsm#2931-2985
If you're hitting this on every startup, logging the contents of updateReasons to figure out what addon change is being applied would be a good place to start.

Comment 3

[Andrew Creskey [:acreskey]]

Thank you Andrew.

I've been looking into this and with my local build (with logging), the update reason that I'm seeing is: appChanged
https://searchfox.org/mozilla-central/rev/8a0745cd346f0cfb89ae71690babbf7bff706113/toolkit/mozapps/extensions/internal/XPIProvider.jsm#2932

The tricky part is that the profiles we are using ("conditioned profiles") are generated as a daily cron job in taskcluster.
So I think it could be appChanged or potentially some other reason (maybe hasPendingChanges ?).

On Android, do you know when this database would normally be serialized?
Is is after a fixed amount of time, post-startup?

Comment 4

[Andrew Creskey [:acreskey]]

Oh, interesting.
When I run the conditioning locally, I'm seeing these update reasons, directoryState,schemaChanged.

So far I've only be able to trigger these processFileChanges() using tests, but not in real user flows.

Comment 5

[Andrew Creskey [:acreskey]]

(In reply to Andrew Creskey [:acreskey] [he/him] from comment #4)

Oh, interesting.
When I run the conditioning locally, I'm seeing these update reasons, directoryState,schemaChanged.

Oops, in this case I was using a profile from the wrong platform.

Using profiles generated from the actual device, and with the same binary, I haven't been able to reproduce the processFileChanges().

Comment 6

[Andrew Swan [:aswan]]

(In reply to Andrew Creskey [:acreskey] [he/him] from comment #3)

I've been looking into this and with my local build (with logging), the update reason that I'm seeing is: appChanged

That means that Services.appinfo.version is something different than it was the last time you started this profile. If you run the same app version again in the same profile, you should not enter processFileChanges().

On Android, do you know when this database would normally be serialized?
Is is after a fixed amount of time, post-startup?

Sorry, I don't understand the question. What database?

Comment 7

[Andrew Creskey [:acreskey]]

I've been looking into this and with my local build (with logging), the update reason that I'm seeing is: appChanged

That means that Services.appinfo.version is something different than it was the last time you started this profile. If you run the same app version again in the same profile, you should not enter processFileChanges().

Thanks, that matches what I'm seeing in local testing -- I only see processFileChanges() with a mismatch between profile and gecko binary.

On Android, do you know when this database would normally be serialized?
Is is after a fixed amount of time, post-startup?

Sorry, I don't understand the question. What database?

I had it in my head that these files were stored in a database, but evidently not.
More for curiosity -- what files in the profile are being scanned by processFileChanges()

Comment 8

[Andrew Creskey [:acreskey]]

Since we're not seeing this issue in real user flows, I suggest we resolve it.

Comment 9

[Andrew Swan [:aswan]]

(In reply to Andrew Creskey [:acreskey] [he/him] from comment #7)

I had it in my head that these files were stored in a database, but evidently not.
More for curiosity -- what files in the profile are being scanned by processFileChanges()

This code is looking at the contents of the extensions/ directory inside the current profile. We generally don't scan it synchronously during startup, though when the application changes we do for various reasons. Information about the set of installed extensions in a given profile is stored in a file called extensions.json. This information used to be stored in sqlite so you might see if referred to as a database in places. But this file is also not touched during a normal startup.

It looks like you intended to resolve this, sorry if I misunderstood.

Comment 10

[Andrew Creskey [:acreskey]]

Thanks, that's very helpful.
Resolved is what I intended.