1899015 - Firefox slow startup after reboot (high disk IO)

Status: UNCONFIRMED

(Core :: Storage: IndexedDB, defect, P2)

Description

[[:Ruliane]]

Attachment: Firefox 2024-05-26 11.39 profile.json.gz

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:126.0) Gecko/20100101 Firefox/126.0

Steps to reproduce:

1. Reboot
2. Start Firefox

Actual results:

The Firefox window appears, but it does nos loads any page until a long time (several dozen of seconds). During this time, there is a high disk IO usage.
Closing and re-starting Firefox works fine.

Very similar to bugs 1567863 and 1778374.

See attached profile.

Expected results:

Firefox should start and show me a webpage in a couple of seconds.

Comment 1

[Rob Wu [:robwu]]

(linking bug 1567863 because user-observed behavior is similar; and bug 1778374 because the reported I/O usage is also seen there)

When I open your attached profile at profiler.firefox.com, I see that there is one (first?) request that takes 48.7 seconds to complete despite it being loaded from the cache. The request is paused because uBlock Origin blocks network requests until it is able to process them, and Firefox somehow takes 44 seconds to initialize the underlying storage (IndexedDB), as seen in the profile:

• 3 seconds in, the extension process starts.
• 5 seconds in, uBlock Origin starts initializing and calls the storage.local.get() API.
  According to the Marker Table in the profile, the duration of the call is 44.677 seconds (search for WEBEXT_STORAGE_LOCAL_IDB_GET).
• 49 seconds in, the storage.local.get call resolves finally, and uBlock Origin continues initialization (onFilterListsReady -> onDone, at https://github.com/gorhill/uBlock/blob/1.58.0/src/js/storage.js#L1010-L1016)
• 50 seconds in, network requests are being processed.
• 51 seconds in, the first request finally completes, after a total delay of 48.7 seconds.

The big question here is why storage.local.get is taking so long. Back to the Marker Chart table, I see that the underlying IndexedDB backend that backs the storage.local API is taking a considerable amount of time:

• 4.708 seconds in, PBackgroundIDBFactory::Msg_PBackgroundIDBFactoryRequestConstructor is sent to Parent Process (sent from IDBFactory::InitiateRequest, handled by Factory::RecvPBackgroundIDBFactoryRequestConstructor in ActorsParent.cpp).
• 49.198 seconds in, PBackgroundIDBFactory::Msg_PBackgroundIDBDatabaseConstructor is received from Parent Process (sent from OpenDatabaseOp::EnsureDatabaseActorIsAlive before the actual response is sent by OpenDatabaseOp::SendResults).

I don't know why this is taking so long, but I'll move it to the Storage product for further triage.

Comment 2

[Rob Wu [:robwu]]

(linking bug 1567863 because user-observed behavior is similar; and bug 1778374 because the reported I/O usage is also seen there)

... and linking bug 1778472 because it also involves an excessive delay before initialization of the storage, localStorage in that case.

Comment 3

[Jens Stutte [:jstutte]]

Hi Ruliane, thanks for filing this! If this still reproduces for you - would you mind to rerun the profiler with "Bypass selections above and record all registered threads" enabled in the settings? This would give much more insights on what is really happening, as the IndexedDB threads are not recorded by default.

Please note also that you can use the "Upload local profile" button in the profiler once it opened locally to safely share your profile (leaving out some sensitive information, if you wish). This will give you a link you can share here.

In general it is very likely that this is another instance of why we want bug 1671932, but the profile would confirm that.

Comment 4

[[:Ruliane]]

Hi Rob and Jens,

Thanks you for the first analysis.
I selected "Bypass selections above and record all registered threads" and captures a new profile: https://share.firefox.dev/3KfSZro

After several tries, it looks like the startup is much slower when Firefox was killed (OS rebooted withoud cleanly closing Firefox) and uBlockOrigin is enabled. Should I upload a profile with all extensions disabled?

Comment 5

[Jens Stutte [:jstutte]]

Attachment: profile_info.png

Are you sure you took that profile with that setting? If I do that here I get ~40 threads only for the parent process (and the threads I am looking for are not in your profile, but here I see them).

Comment 6

[Jens Stutte [:jstutte]]

Ah, wait, I think it is the upload that removes some threads. When uploading please tick "Include hidden threads". I fear that means to take it once again, sorry for the hassle.

Comment 7

[[:Ruliane]]

Here is the same profile with hidden threads: https://share.firefox.dev/3yC62AU

Also, are you sure the startup profile follows this setting? Or should I start Firefox with a MOZ_PROFILER_* environment variable?

Comment 8

[Jens Stutte [:jstutte]]

(In reply to [:Ruliane] from comment #7)

Here is the same profile with hidden threads: https://share.firefox.dev/3yC62AU

Also, are you sure the startup profile follows this setting? Or should I start Firefox with a MOZ_PROFILER_* environment variable?

I see more threads but still not those I expected to see, so probably you are right and need to set MOZ_PROFILER_STARTUP_FILTERS="*". You can check in your local profile if you see an IndexedDB IO #<n> thread, at least.

Comment 9

[[:Ruliane]]

Here is a new profile with the following command: MOZ_PROFILER_STARTUP=1 MOZ_PROFILER_STARTUP_INTERVAL=10 MOZ_PROFILER_STARTUP_FILTERS="*" firefox: https://share.firefox.dev/4bCzUMi
Hope you'll find something useful.

Comment 10

[Jens Stutte [:jstutte]]

(In reply to [:Ruliane] from comment #9)

Here is a new profile with the following command: MOZ_PROFILER_STARTUP=1 MOZ_PROFILER_STARTUP_INTERVAL=10 MOZ_PROFILER_STARTUP_FILTERS="*" firefox: https://share.firefox.dev/4bCzUMi
Hope you'll find something useful.

Thanks! Yes, the long running function on the QuotaManager IO thread is QuotaManager::EnsureTemporaryStorageIsInitializedInternal(), triggered at the first attempt to open an IndexedDB database. Bug 1671932 will help to mitigate this. I was not able to really count them, but apparently your profile contains a pretty high number of origins, with some of them pretty heavyweight.

Comment 11

[[e-mail]]

your profile contains a pretty high number of origins, with some of them pretty heavyweight.

Ruliane, you should go to Settings, search for Manage Data button, then click it, then you should delete the entries which are not useful. Reducing the overall size should reduce the readiness time.

Comment 12

[[:Ruliane]]

I already deleted some heavy sites in Manage Data before capturing the profile. It helped reducing the startup time but still far beyond a reasonable time.

My profile is several years old so it certainly contains lots of (obsolete?) stuff. Is there a way to delete very old entries?

(BTW, I don't know how an IndexedDB works or what origin means in this context.)

Comment 13

[Jens Stutte [:jstutte]]

"Origin" means basically a web-site. For each origin there are dedicated folders on disk inside the profile. Via Settings -> Privacy & Security -> Cookies and Site Data you can select "Manage Data" and in the dialog sort the web sites by "Last Used".

Comment 14

[[e-mail]]

Just to be sure, I see you have an extension called "Textarea Cache", maybe disable it and launch Firefox again to see if this makes a difference.

Comment 15

[Ed]

(In reply to [e-mail] from comment #14)

Just to be sure, I see you have an extension called "Textarea Cache", maybe disable it and launch Firefox again to see if this makes a difference.

FWIW, I've been using Textarea Cache for several years and have entries going back to June 2020. Never had startup issues. However, if there's some corruption in that data, it's possible to cause problems.

@Ruliane, have you tried opening FF in Troubleshoot mode right after reboot?

Comment 16

[[:Ruliane]]

A bunch of test later...

Slow startup appears even with all extensions disabled and in troubleshoot mode. Here is a profile captured in such a situation: Capture KILL+safemode

However, so far I rebooted without quitting the browser, meaning that Firefox is killed with several tabs in use and has to restore them at startup. If I softly close all tabs before rebooting, the startup is faster. My homepage loads instantly BUT huge disk IO happen in background, sometimes blocking others actions (like loading another page, or opening a tab): Capture SOFTQUIT+safemode

Look like I have to wait for a fix for bug #1671932.

Comment 19

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

The severity field for this bug is set to S3. However, the following bug duplicate has higher severity:

• Bug 1741865: S2

:aiunusov, could you consider increasing the severity of this bug to S2?

For more information, please visit BugBot documentation.

Comment 20

[foxy]

As workaround you can create a new firefox profile.
Or use an addon like https://addons.mozilla.org/de/firefox/addon/clear-browsing-data/
to clean the IndexedDB data. It may take some minutes but after that firefox is fast again after startup.