1871799 - High CPU Usage by QuotaManager IO Thread since Firefox 122 b2

Status: RESOLVED FIXED

(Core :: Storage: Quota Manager, defect, P2)

Description

[[:FSpark]]

Attachment: firefox_glegZTx1Ix.png

Steps to reproduce:

Simply open Firefox Developer Edition 122.0b2 on Windows 10 21H2 (my enviorment).

Actual results:

Then it gets incredibly stuck, and I can barely access any web pages.
The issue persists even when starting Firefox in Troubleshoot Mode, with all extensions and personal configurations temporarily disabled.

The following is what I did to locate the problem. Please let me know if there's anything else I can assist you with.

Expected results:

There is no longer high CPU usage even during idle periods.

Comment 1

[[:FSpark]]

Using mozregression seems to locate the problem, which seems to be related to Bug 1866240 .

https://phabricator.services.mozilla.com/D195081

Here are the logs.

app_name: firefox
build_date: 2023-12-04 11:32:48.803000
build_file: F:/Cache/moz\d8bdabb500fb-pgo--autoland--target.zip
build_type: integration
build_url: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ZMGWfLRzSQKWtXXIJG6vSw/runs/0/artifacts/public%2Fbuild%2Ftarget.zip
changeset: d8bdabb500fbfe7bf06cca37b0a49d1ff4b4ecbd
pushlog_url: https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=d8bdabb500fbfe7bf06cca37b0a49d1ff4b4ecbd&tochange=1d035302ec6286fa9ff1584b21cc51b084a2644b
repo_name: autoland
repo_url: https://hg.mozilla.org/integration/autoland
task_id: ZMGWfLRzSQKWtXXIJG6vSw

2023-12-24T21:20:10.506000: INFO : platform_repository: https://hg.mozilla.org/integration/autoland
2023-12-24T21:20:10.506000: INFO : platform_version: 122.0a1
2023-12-24T21:20:33.585000: INFO : Narrowed integration regression window from [f5150abd, 1d035302] (3 builds) to [d8bdabb5, 1d035302] (2 builds) (~1 steps left)
2023-12-24T21:20:33.598000: DEBUG : Starting merge handling...
2023-12-24T21:20:33.598000: DEBUG : Using url: https://hg.mozilla.org/integration/autoland/json-pushes?changeset=1d035302ec6286fa9ff1584b21cc51b084a2644b&full=1
2023-12-24T21:20:33.598000: DEBUG : redo: attempt 1/3
2023-12-24T21:20:33.599000: DEBUG : redo: retry: calling _default_get with args: ('https://hg.mozilla.org/integration/autoland/json-pushes?changeset=1d035302ec6286fa9ff1584b21cc51b084a2644b&full=1',), kwargs: {}, attempt #1
2023-12-24T21:20:33.611000: DEBUG : urllib3.connectionpool: Resetting dropped connection: hg.mozilla.org
2023-12-24T21:20:35.341000: DEBUG : urllib3.connectionpool: https://hg.mozilla.org:443 "GET /integration/autoland/json-pushes?changeset=1d035302ec6286fa9ff1584b21cc51b084a2644b&full=1 HTTP/1.1" 200 None
2023-12-24T21:20:35.376000: DEBUG : Found commit message:
Bug 1866240 - Maintain usage information in the database; r=dom-storage-reviewers,asuth

Differential Revision: https://phabricator.services.mozilla.com/D195081

Comment 2

[[:FSpark]]

Firefox Profiler: https://share.firefox.dev/3RVBqS3

Comment 3

[BugBot [:suhaib / :marco]]

Set release status flags based on info from the regressing bug 1866240

:janv, since you are the author of the regressor, bug 1866240, could you take a look? Also, could you set the severity field?

For more information, please visit BugBot documentation.

Comment 4

[Jan Varga [:janv]]

The high cpu usage shouldn't be persistent, there's one-time upgrade which can cause the high cpu usage, but things should be much faster after that. See also this description of the fix: bug 1866240 comment 10.

The telemetry for FF beta 122 confirms it:
https://glam.telemetry.mozilla.org/firefox/probe/qm_quota_info_load_time_v0/explore?channel=beta&currentPage=1&process=parent&ref=20231211174248&timeHorizon=QUARTER&visiblePercentiles=%5B99.9%2C99%2C95%2C75%2C50%2C5%5D

Comment 5

[Jan Varga [:janv]]

Just to be sure your profile (specifically <profile>/storage) is ok, can you go to the browser console and check if there are any errors mentioning QM_TRY ?

Please check status of individual storage APIs at https://firefox-storage-test.glitch.me as well.

Thanks

Comment 6

[Andrew Sutherland [:asuth] (he/him)]

(In reply to Jan Varga [:janv] from comment #5)

Just to be sure your profile (specifically <profile>/storage) is ok, can you go to the browser console and check if there are any errors mentioning QM_TRY ?

Docs on accessing the browser console are here: https://firefox-source-docs.mozilla.org/devtools-user/browser_console/index.html

Given the bisection and that this continues to happen, it does seem likely something must be failing so that forward progress is not being made.

The profiler trace from comment 2 seems to show LS triggering temporary storage initialization twice in succession by viewing in stack chart mode which gives a chronological display (rather than the flame chart merging everything).

Comment 7

[[:FSpark]]

The Browser Console is full of errors and firefox-storage-test shows Totally Broken.

firefox-storage-test Debug Info:

storage.estimate() threw: Internal error while estimating storage usage
Failed to create "persistent" IDB.
Failed to create "transient" IDB.

{
  "v": 1,
  "curVersion": 122,
  "prevVersion": 0,
  "ls": {},
  "qm": {
    "lastWorkedIn": 0
  },
  "idb": {
    "persistentCreatedIn": 0,
    "persistentLastOpenedIn": 0,
    "clearDetectedIn": 0
  },
  "cache": {
    "firstCacheCreatedIn": 0,
    "unpaddedOpaqueCreatedIn": 0,
    "paddedOpaqueCreatedIn": 0
  }
}

Please see the attachment for Browser Console Log details.

Comment 8

[[:FSpark]]

Attachment: Browser Console Log

Comment 9

[[:FSpark]]

Overview:
Storage is broken. This is your first visit or all storage was automatically cleared.
Specific Subsystem Statuses:

LocalStorage
Bad: Our test logic is broken, please copy and paste the contents of 'Debug Info' below and anything in the devtools console and send to :asuth. (unexpectedBreakage)
QuotaManager
Bad: Totally Broken. (fullyBroken)
IndexedDB
Bad: Totally Broken. (fullyBroken)
Cache API
Bad: Totally Broken. (fullyBroken)

Comment 10

[Jan Varga [:janv]]

Ok, that's really helpful, let me investigate what is failing.

Comment 11

[Donal Meehan [:dmeehan]]

:janv re: Comment 10, any updates on your investigation?

Comment 12

[Jan Varga [:janv]]

Yeah, I have a rough plan for that, but before i submit a patch for review, I'm waiting for some people to be back (after holidays) and get a confirmation of the plan.

Comment 13

[Jan Varga [:janv]]

FSpark, is it possible to share your <profile>/storage directory privately ?
If not, would you be ok with downloading a Firefox build from our try server and running it with a copy of your profile ?
Thanks.

Comment 14

[[:FSpark]]

I'm sorry that due to some privacy issues, such as company business data, I can't share it with you, but I am happy to cooperate with the test!

Where can I download the test version? It doesn't seem to be available on treeherder either.

Thanks.

Comment 15

[Jan Varga [:janv]]

(In reply to [:FSpark] from comment #14)

Where can I download the test version? It doesn't seem to be available on treeherder either.

I'll provide try builds soon, I needed to know first how we can test potential fixes because there are multiple options how to fix this bug.

Comment 16

[Jan Varga [:janv]]

Just to be sure about the fix, I submitted a debugging patch to try:
https://treeherder.mozilla.org/jobs?repo=try&revision=e0289b9c51f7af66dbb7819aa3d948d3ce97e65e

It's still being processed.
Once builds are available, I'll submit an exact link to a windows build with simple instructions how to use it (what to check).

Comment 17

[Jan Varga [:janv]]

Ok, here's a windows x64 build: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/MSlkeO89QrePzJqoRPGPzw/runs/0/artifacts/public/build/target.zip

Can you run it with the profile which causes the reported problem ?
You should see in the browser console something like "Can't open cache database, file path: ..."
It should appear close to "QM_TRY failure (ERROR): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/cache/DBAction.cpp:215"
As always, use a backup of the profile for any experiments like this.

Once we have the file path, we can focus on exact origin directory on disk which you could eventually send me or provide at least a directory listing of it.

Thanks.

Comment 18

[Jan Varga [:janv]]

I'm testing a possible fix: https://treeherder.mozilla.org/jobs?repo=try&revision=9063c833abf5b16fdff853f5220d39e0c2e33be9

Comment 19

[[:FSpark]]

I think I might know why - maybe it's some special domain names: Domain names with dots at the end, like foo.bar.com.

Error log (cleaned):

QM_TRY failure (WARNING): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/cache/DBAction.cpp:227
Quota Can't open cache database, file path: \\?\C:\Users\Okabe\AppData\Roaming\Mozilla\Firefox\Profiles\i4ohzi64.default-release\storage\default\https+++foo.bar.com.\cache\caches.sqlite: DBAction.cpp:215
QM_TRY failure (ERROR): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/cache/DBAction.cpp:226
QM_TRY failure (ERROR): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/cache/DBAction.cpp:227
QM_TRY failure (ERROR): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/cache/QuotaClient.cpp:113
QM_TRY failure (ERROR): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/cache/QuotaClient.cpp:236
QM_TRY failure (ERROR): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/quota/ActorsParent.cpp:3781
QM_TRY failure (ERROR): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/quota/ActorsParent.cpp:3855
QM_TRY failure (ERROR): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/quota/ActorsParent.cpp:3643 2
QM_TRY failure (ERROR): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/quota/ActorsParent.cpp:3668
QM_TRY failure (ERROR): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/quota/ActorsParent.cpp:2879
QM_TRY failure (ERROR): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/quota/ActorsParent.cpp:5471
QM_TRY failure (ERROR): 'Unavailable failed with resultCode 0x80520015, resultName NS_ERROR_FILE_ACCESS_DENIED, context dom::localstorage::FirstOriginInitializationAttempt::Datastore', file dom/localstorage/ActorsParent.cpp:6922
Quota Can't open cache database, file path: \\?\C:\Users\Okabe\AppData\Roaming\Mozilla\Firefox\Profiles\i4ohzi64.default-release\storage\default\https+++foo.bar.com.\cache\caches.sqlite: DBAction.cpp:215

Background:

• google chrome - Why does putting a dot after the URL remove login information? - Super User
• dns - Domain names with dots at the end - Stack Overflow

Due to some special and legacy reasons, some websites can only be accessed in this special way, and both Cookie and LocalStorage will store them as a completely new and different domain.

Comment 20

[Jan Varga [:janv]]

Ok, that helps a lot, thank you.

We already fixed a problem with a trailing dot some time ago, but it seems there's still something which can't handle it, probably SQLite.
Let me quickly check.

Comment 21

[Donal Meehan [:dmeehan]]

Hi :janv, we are in the last week of beta for Fx122. 122.0b9 builds on 2024-01-12.
Do you think you might have something in time?
Wondering if you still think it's S3 after your investigation.

Comment 22

[Jan Varga [:janv]]

Yes, I'm submitting patches for review today and I already spoke with asuth about it to take a look today as well.

Comment 23

[Jan Varga [:janv]]

Attachment: Bug 1871799 - Expose GetStorageConnection via FileSystemDataManager.h; r=#dom-storage

Some tests will need to create a connection to check usage when storage is not
initialized.

Comment 24

[Jan Varga [:janv]]

Attachment: Bug 1871799 - Remove redundant GetStorageConnection overload; r=#dom-storage

There are two similar GetStorageConnection overloads. The only difference is
that they use different mozIStorageService methods for database opening.
The overloads can be easilly merged into just one method, so database opening
will be done using mozIStorageService::GetDatabaseFileURL even when called
from FileSystemQuotaClient::InitOrigin.

Depends on D194519

Comment 25

[Jan Varga [:janv]]

Attachment: Bug 1871799 - Allow calling QuotaManager::GetQuotaObject for unregistered directory locks; r=#dom-storage

The method now returns nullptr instead of crashing parent process when there's
no registered directory lock for given directory lock id.

Depends on D198186

Comment 26

[Jan Varga [:janv]]

Attachment: Bug 1871799 - Fix relevant quota clients to always use QuotaVFS for database access; r=#dom-storage

Some quota clients currently use the BaseVFS (instead of QuotaVFS) during
origin initialization which makes sense at first glance (there's no need to
track usage when temporary storage is only being initialized).
However, QuotaVFS provides other important functionality besides quota checks
which is the overridden xFullPathname method. The overridden implementation is
needed to avoid file path normalization on Windows.
This patch changes relevant quota clients to always use QuotaVFS, even during
origin initialization to take advantage of the overriden xFullPathname method.
There will be no quota checks during origin initialization just like before
because the passed directory lock id is -1. GetQuotaObject will return nullptr
in that case.

Depends on D198187

Comment 27

[Jan Varga [:janv]]

I'm testing a fix on try: https://treeherder.mozilla.org/jobs?repo=try&revision=59307bcacee4972f4e19cc7323b48404c067b36a
I'll provide exact link to a windows builds once it's available.

Comment 28

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/cfcfffff92a1
Expose GetStorageConnection via FileSystemDataManager.h; r=dom-storage-reviewers,asuth
https://hg.mozilla.org/integration/autoland/rev/77ae57e2a35b
Remove redundant GetStorageConnection overload; r=dom-storage-reviewers,asuth
https://hg.mozilla.org/integration/autoland/rev/bca55125e866
Allow calling QuotaManager::GetQuotaObject for unregistered directory locks; r=dom-storage-reviewers,asuth
https://hg.mozilla.org/integration/autoland/rev/d22fed811153
Fix relevant quota clients to always use QuotaVFS for database access; r=dom-storage-reviewers,asuth

Comment 29

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/cfcfffff92a1
https://hg.mozilla.org/mozilla-central/rev/77ae57e2a35b
https://hg.mozilla.org/mozilla-central/rev/bca55125e866
https://hg.mozilla.org/mozilla-central/rev/d22fed811153

Comment 30

[BugBot [:suhaib / :marco]]

The patch landed in nightly and beta is affected.
:janv, is this bug important enough to require an uplift?

• If yes, please nominate the patch for beta approval.
• If no, please set status-firefox122 to wontfix.

For more information, please visit BugBot documentation.

Comment 31

[Jan Varga [:janv]]

Comment on attachment 9372065 [details]
Bug 1871799 - Fix relevant quota clients to always use QuotaVFS for database access; r=#dom-storage

Beta/Release Uplift Approval Request

• User impact if declined: Some users on Windows would experience broken storage (indexedDB, cache API, localStorage not working for any site) and potentially high CPU usage if they ever browsed a site with a trailing dot.
• Is this code covered by automated tests?: No
• Has the fix been verified in Nightly?: Yes
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): The fix has been manually tested.
• String changes made/needed: None
• Is Android affected?: No

Comment 32

[Donal Meehan [:dmeehan]]

Comment on attachment 9372053 [details]
Bug 1871799 - Expose GetStorageConnection via FileSystemDataManager.h; r=#dom-storage

Approved for 122.0b9

Comment 33

[Donal Meehan [:dmeehan]]

Comment on attachment 9372056 [details]
Bug 1871799 - Remove redundant GetStorageConnection overload; r=#dom-storage

Approved for 122.0b9

Comment 34

[Donal Meehan [:dmeehan]]

Comment on attachment 9372059 [details]
Bug 1871799 - Allow calling QuotaManager::GetQuotaObject for unregistered directory locks; r=#dom-storage

Approved for 122.0b9

Comment 35

[Donal Meehan [:dmeehan]]

Comment on attachment 9372065 [details]
Bug 1871799 - Fix relevant quota clients to always use QuotaVFS for database access; r=#dom-storage

Approved for 122.0b9

Comment 36

[Pulsebot]

https://hg.mozilla.org/releases/mozilla-beta/rev/4975318e53a9
https://hg.mozilla.org/releases/mozilla-beta/rev/0815bc99cc5c
https://hg.mozilla.org/releases/mozilla-beta/rev/3fea84d150bb
https://hg.mozilla.org/releases/mozilla-beta/rev/f1680a61c014