Bug 202137 – IndexedDB WAL file keeps growing while app is in use

• Component: New Bugs
• Status: RESOLVED FIXED

[Radek Pietruszewski]

IndexedDB size calculations seem buggy, leading to very bad user experience. Our web app (4.nozbe.com) is based on LokiJS, which uses IndexedDB only as a storage mechanism -- and so it saves the entire LokiJS data object in just one IndexedDB row.

On a fairly large account, the database size can grow up too 100MB.

And yet, after a few database operations, Safari asks the user for >1GB of storage… after accepting, and a few database operations (each of which will save the new version of database to disk, but keeping below <100MB of size of both the database and WAL/SHL files), it will ask for 1.2GB… 1.4GB… every couple of minutes.

This is a regression in Safari 13 / Safari TP. The issue does not occur on Safari 12. I suspect this Webkit commit might be the cause of the issue: https://github.com/WebKit/webkit/commit/36aa2f1a9d05d9efdcf41929c206e2dfdc6e6ded#diff-714b919c798f296a141098072faac979

(originally posted as https://feedbackassistant.apple.com/feedback/7315350)

. . .

I extracted a repro demo here (the numbers are a little different, but basic principle is the same):

https://web.radexpl.now.sh/

1. open in safari 13 / safari TP,
2. click "generate 10,000 records" a few times, open first item on the list, click "moderate", try with second item, click generate 10,000 items again — after a few of these actions (<30 seconds to reproduce), Safari will ask if it can increase db size to 1.2GB
3. click yes or refresh page - then check under `/Users/radex/Library/SafariTechnologyPreview/Databases/___IndexedDB/v1/https_web.radexpl.now.sh_0/` - database won't be actually larger than 250MB

[Radar WebKit Bug Importer]

<rdar://problem/55722145>

[Sihui Liu]

(In reply to radexpl from comment #0)
> IndexedDB size calculations seem buggy, leading to very bad user experience.
> Our web app (4.nozbe.com) is based on LokiJS, which uses IndexedDB only as a
> storage mechanism -- and so it saves the entire LokiJS data object in just
> one IndexedDB row.
> 
> On a fairly large account, the database size can grow up too 100MB.
> 
> And yet, after a few database operations, Safari asks the user for >1GB of
> storage… after accepting, and a few database operations (each of which will
> save the new version of database to disk, but keeping below <100MB of size
> of both the database and WAL/SHL files), it will ask for 1.2GB… 1.4GB… every
> couple of minutes.
> 
> This is a regression in Safari 13 / Safari TP. The issue does not occur on
> Safari 12. I suspect this Webkit commit might be the cause of the issue:
> https://github.com/WebKit/webkit/commit/
> 36aa2f1a9d05d9efdcf41929c206e2dfdc6e6ded#diff-
> 714b919c798f296a141098072faac979
> 
> (originally posted as https://feedbackassistant.apple.com/feedback/7315350)
> 
> . . .
> 
> I extracted a repro demo here (the numbers are a little different, but basic
> principle is the same):
> 
> https://web.radexpl.now.sh/
> 
> 1. open in safari 13 / safari TP,
> 2. click "generate 10,000 records" a few times, open first item on the list,
> click "moderate", try with second item, click generate 10,000 items again —
> after a few of these actions (<30 seconds to reproduce), Safari will ask if
> it can increase db size to 1.2GB
> 3. click yes or refresh page - then check under
> `/Users/radex/Library/SafariTechnologyPreview/Databases/___IndexedDB/v1/
> https_web.radexpl.now.sh_0/` - database won't be actually larger than 250MB

Hi,

I just tried the steps above on Safari 13. I saw the "increase db size to 1.2GB", but only on when the database file sizes reach over or about 1GB. I noticed that the display of file size in Finder app may be delayed. If you were using Finder, can you try re-opening Finder probably a few seconds after you see the notification and confirm total database file size is much smaller than 1GB?

Thanks.

[Radek Pietruszewski]

Hi Sihui,

You're right. I misread the nature of the issue, because Finder doesn't seem to want to update file sizes at all on my computer...

I switched to checking sizes with `du -sh *` and I can confirm that the WAL size does indeed keep growing to the numbers Safari is asking the user about. I also checked and Safari 12.1.1 does the same thing (just without asking).

In this case, the issue is that WAL keeps growing and growing while the app is in use. When I reload the page, it goes to zero (it used to be worse — but https://bugs.webkit.org/show_bug.cgi?id=191294#c13 fixed it), but the nature of the web app is such that users can be expected to have it open for a long time.

[Ben Lowery]

We're seeing this problem with wp-calypso, a JS driven admin interface for WordPress that's used by WordPress.com. I've extracted a similar, but different, repo at https://github.com/blowery/idb-asplode

Simply inserting the same record into an objectStore over and over will trigger the storage prompt once the WAL grows past 1GB on desktop. 

Clearing the objectStore using .clear() or deleting the db entirely can truncate the log while the page is still loaded, but deleting everything in storage is less than ideal.

[Radek Pietruszewski]

Sihui Liu et al:

Hi. It's been 6 months since this bug has been reported, and there's no change.

This is a SERIOUS bug and will likely affect any app that stores on the order of >100MB of data in IndexedDB. Through normal usage of web apps like this, I will get a lot of questions like "do I want to allow xxxx to use 4GB of storage" (even though 3.9GB of that is just the WAL which could be truncated).

Workarounds are possible, but they don't solve the problem, only slow it down. The WAL keeps growing, just more slowly if you do lots of engineering to split IDB into smaller chunks and check what needs to be committed. So instead of getting the Safari alert after an hour of usage of a complex web app, I'll get it after 1 day. Still, I get a lot of user reports complaining about this, and workaround on my side have diminishing returns, while the underlying problem doesn't seem too difficult.

Please let me know if you want more information from me or I can help to get this resolved.

[Lee Robertson]

This is an issue for me as well. I can see the size of the log growing to 1.2GBs.

Weird thing is that when I call. idb.clear(), sometimes I can get the log to reset but not very reliable.

[Lee Robertson]

Happening as well on the iPad (13.4.1) (In reply to Lee Robertson from comment #6)
> This is an issue for me as well. I can see the size of the log growing to
> 1.2GBs.
> 
> Weird thing is that when I call. idb.clear(), sometimes I can get the log to
> reset but not very reliable.

[Ben Nham]

Going to take a stab at this. From looking at SQLiteIDBBackingStore.cpp, it looks like there are several places where we only step a cached prepared statement until it hits SQLITE_ROW and then immediately return (like uncheckedGetKeyGeneratorValue). The problem is that cursor will hold open a read transaction to that version of the table, preventing checkpointing from ever moving past the pages associated with that version of the table.

We need to ensure all cached prepared statements are iterated until they hit SQLITE_DONE or we sqlite3_reset them; both will cause the associated transaction to be dropped.

[Lee Robertson]

(In reply to Ben Nham from comment #8)
> Going to take a stab at this. From looking at SQLiteIDBBackingStore.cpp, it
> looks like there are several places where we only step a cached prepared
> statement until it hits SQLITE_ROW and then immediately return (like
> uncheckedGetKeyGeneratorValue). The problem is that cursor will hold open a
> read transaction to that version of the table, preventing checkpointing from
> ever moving past the pages associated with that version of the table.
> 
> We need to ensure all cached prepared statements are iterated until they hit
> SQLITE_DONE or we sqlite3_reset them; both will cause the associated
> transaction to be dropped.

Appreciate your time, this is great!

[Ben Nham]

Created attachment 397929 [details]
simple testcase for indefinitely growing wal

I've attached a simplified test case that I just wrote. In the current version of Safari, every time you hit "Add Rows", 25 MB of data will be appended to the WAL without the WAL being auto-checkpointed back into the main DB file. As I wrote above, this is due to various cached prepared statements (in this test case, the count-by-query statement) not being properly reset or iterated to SQLITE_DONE before being placed back into the statement cache. I also tried out a hacky patch and it fixed the issue (WAL file is now auto-checkpointed as expected).

[Ben Nham]

Created attachment 398103 [details]
wal growing testcase 2

Enhanced the attach testcase which has helped me find some more issues.

1. Clicking on "Add 25 MB" causes the WAL to grow by that amount without being checkpointed back to the main DB file. This is due to the cached prepared statement issue described above. I have a pretty clean fix for this in my branch.

2. Even if we fix the cached statement issue above, the WAL still stays in an untruncated state for one write transaction more than expected. This is because the default sqlite3_wal_hook used for auto-checkpointing in upstream sqlite3 uses SQLITE_CHECKPOINT_PASSIVE to checkpoint, which does not truncate the WAL after the checkpoint even if you set journal_size_limit (which should limit the WAL size after checkpointing). Instead truncation is deferred until the next write transaction occurs. We can fix this by using our own WAL hook that checkpoints using SQLITE_CHECKPOINT_TRUNCATE instead. (This can cause unintended delays if you install a busy handler but we don't.) I also have a fix for this.

3. The way we estimate the size of a put in UniqueIDBDatabase::putOrAdd can cause a large overestimation in storage usage when there are a large number of indices. In particular, our estimated write cost is basically:

  (1 + numIndices) * (estimatedPrimaryKeySize + estimatedValueSize)

This is a safe upper bound (accurate to within a constant factor). But it can be a pretty big overestimate in certain cases, since secondary indices do not store the whole value, but rather just a mapping from the secondary index key => primary key.

In particular, in the WatermelonDB demo mentioned in this bug report, there is just a single 220 MB row being added to a table with 3 indices. This leads to a size estimation for the put of 220 MB * 4 = 880 MB which causes a trip over the 1 GB quota almost immediately. The secondary index keys actually do not cover most of the attributes in the stored value so this ends up being a large overestimate in this case.

Performing a more accurate estimated cost would require quite a bit of refactoring and is probably too risky right now. But I have some ideas for other heuristics that I'm working on that might lead to less overestimation.

4. There is also an issue in Safari (which controls the quota increase) where if you do a single gigantic write (say a 1 GB put operation), the browser asks for quota increases in X MB (usually 200 MB) increments rather than in a single 1 GB increment. I will file a bug on that but it will require a Safari rather than WK fix. I don't think this is actually the cause of most complaints here because this quota increase logic in Safari has been in place for a long time. It's more of an edge case that I just stumbled upon.

[Ben Nham]

@radexpl, your webpage https://web.radexpl.now.sh/ seems to behave very differently in Chrome than in Safari when I use it.

In Safari 13.1 (Catalina 10.15.4), when I click "Generate 250000 records", I see a 120MB string (actually 240MB when serialized as UTF-16 in the DB) being written to the DB:

> req = indexedDB.open('LokiCatalog')
< IDBOpenDBRequest {onblocked: null, onupgradeneeded: null, source: null, transaction: null, readyState: "pending", …}
> db = req.result
< IDBDatabase {name: "LokiCatalog", version: 1, objectStoreNames: DOMStringList, onabort: null, onclose: null, …}
> result = db.transaction(['LokiAKV'], 'readwrite').objectStore('LokiAKV').get(2)
< IDBRequest {source: IDBObjectStore, transaction: IDBTransaction, readyState: "pending", onsuccess: null, onerror: null, …}
> result.result
< {app: "WatermelonDemo", key: "WatermelonDemo", appkey: "WatermelonDemo,WatermelonDemo", val: "{\"filename\":\"WatermelonDemo\",\"collections\":[{\"name…e\":[],\"changes\":[],\"warning\":[]},\"ENV\":\"BROWSER\"}", id: 2}
> result.result.val.length
< 119012661

On Chrome 80, I only see a 3.5 KB string in the DB:

> req = indexedDB.open('LokiCatalog')
< IDBOpenDBRequest {onblocked: null, onupgradeneeded: null, source: null, transaction: null, readyState: "pending", …}
> db = req.result
< IDBDatabase {name: "LokiCatalog", version: 1, objectStoreNames: DOMStringList, onabort: null, onclose: null, …}
> result = db.transaction(['LokiAKV'], 'readwrite').objectStore('LokiAKV').get(2)
< IDBRequest {source: IDBObjectStore, transaction: IDBTransaction, readyState: "pending", onsuccess: null, onerror: null}
> result.result
< {app: "WatermelonDemo", key: "WatermelonDemo", appkey: "WatermelonDemo,WatermelonDemo", val: "{"filename":"WatermelonDemo","collections":[{"name…e":[],"changes":[],"warning":[]},"ENV":"BROWSER"}", id: 2}
> result.result.val.length
< 3495

Is this expected?

Note that this does not block me from making progress on the issues I identified above--those are real bugs that I am preparing patches for.

[Ben Nham]

Created attachment 398306 [details]
Patch

[Ben Nham]

See https://bugs.webkit.org/show_bug.cgi?id=211360 for improvements to the estimated write size calculation.

[Brady Eidson]

Comment on attachment 398306 [details]
Patch

Looks good.

I don't love the SQLiteStatementAutoResetScope class name. It's really more of "a SQLiteStatement that knows when to reset itself", but the class name suggests "a scope that resets SQLiteStatements"

But I can't think of an obviously clearer name.

[Ben Nham]

Created attachment 398407 [details]
Patch

[EWS]

Committed r261141: <https://trac.webkit.org/changeset/261141>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 398407 [details].

[Lee Robertson]

Is there any info on when the fix will be released?

[Ben Nham]

This was first released in Safari Technology Preview 107:

https://webkit.org/blog/10585/release-notes-for-safari-technology-preview-107/

This patch isn't highlighted in the release notes under the IndexedDB section but I'm working on changing that.