1358780 - Crash in SQLiteHistory.getModifiedHistoryToUpload (OOM)

Status: RESOLVED FIXED

(Firefox for iOS :: Sync, defect, P1)

Description

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

This is a hard to investigate crash that happens for some of our users. We have two people at Mozilla who are experiencing this crash and they are currently running the v7.x-debug branch to collect more information.

The sync.log ends with the following:

[Profile.swift:1173] syncWith > Syncing history…
[Profile.swift:1063] syncHistoryWithDelegate(_:prefs:ready:) > Syncing history to storage.
[Synchronizer.swift:159] init(scratchpad:delegate:basePrefs:collection:) > Synchronizer configured with prefs 'profile.sync.synchronizer.history...'
[Profile.swift:1278] greenLight() > Checking green light. Backgrounded: false.
[Downloader.swift:45] init(collectionClient:basePrefs:collection:) > Downloader configured with prefs 'profile.sync.synchronizer.history..downloader.history..'.
[Downloader.swift:127] go(_:limit:) > Modified: 1492816850430; last 1492816850430.
[Downloader.swift:129] go(_:limit:) > No more data to batch-download.
[HistorySynchronizer.swift:232] onBatchResult > No new data. No need to continue batching.
[HistorySynchronizer.swift:164] uploadOutgoingFromStorage(_:lastTimestamp:withServer:) > Uploading 0 deleted places.
[IndependentRecordSynchronizer.swift:88] uploadRecords(_:lastTimestamp:storageClient:onUpload:) > No modified records to upload.

At that point the device runs out of memory and the application is killed.

A normal session is supposed to continue with at least:

[HistorySynchronizer.swift:175] uploadOutgoingFromStorage(_:lastTimestamp:withServer:) > Uploading 0 modified places.
[HistorySynchronizer.swift:126] uploadModifiedPlaces(_:lastTimestamp:fromStorage:withServer:) > Preparing upload…
[HistorySynchronizer.swift:189] uploadOutgoingFromStorage(_:lastTimestamp:withServer:) > Done syncing. Work was done? false
[HistorySynchronizer.swift:191] uploadOutgoingFromStorage(_:lastTimestamp:withServer:) > Done.

This makes me believe this bug is most likely related to SQLiteHistory.getModifiedHistoryToUpload()

More information to follow from added debug logging.

Comment 1

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

Some thoughts:

Is it possible the query will return a crazy amount of data for people who have a lot of history? Should we chunk this? I see that one of the arguments to the sql query is a HAVING COUNT(*) < ? to limit the number of visits per history item. But what if you have thousands of modified history items? Maybe this query needs to be able to do the work in chunks?

Does the query actually do the right thing?

The last build has more logging and also logs total memory usage while this function is running and while it is fetching records.

The last build also prints out a directory listing of the app cointainer so that we can see if the -wal files are insanely large.

Comment 2

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

See https://github.com/mozilla-mobile/firefox-ios/pull/2655

Comment 3

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

Data from tester 1:

Profile database sizes:

profile.profile/ReadingList.db 16384
profile.profile/TabManagerScreenshots 0
profile.profile/browser.db 100990976
profile.profile/browser.db-shm 32768
profile.profile/browser.db-wal 688664
profile.profile/customEngines.plist 5830
profile.profile/logins.db 129024
profile.profile/logins.db-shm 32768
profile.profile/logins.db-wal 0

Note how browser.db is 100MB

Sync log:

[Profile.swift:1173] syncWith > Syncing history…
[Profile.swift:1063] syncHistoryWithDelegate(_:prefs:ready:) > Syncing history to storage.
[Synchronizer.swift:159] init(scratchpad:delegate:basePrefs:collection:) > Synchronizer configured with prefs 'profile.sync.synchronizer.history...'
[Profile.swift:1278] greenLight() > Checking green light. Backgrounded: false.
[Downloader.swift:45] init(collectionClient:basePrefs:collection:) > Downloader configured with prefs 'profile.sync.synchronizer.history..downloader.history..'.
[Downloader.swift:127] go(_:limit:) > Modified: 1492878088080; last 1492827272010.
[Downloader.swift:157] downloadNextBatchWithLimit(_:infoModified:) > Fetching newer=1492827272010, offset=nil.
[StorageClient.swift:757] getSince(_:sort:limit:offset:) > Issuing GET with newer = 1492827272010, offset = nil, sort = Optional(Sync.SortOption.OldestFirst).
[StorageClient.swift:357] failFromResponse > Status code: 200.
[Downloader.swift:175] handleSuccess > Handling success.
[Downloader.swift:209] handleSuccess > Got success response with 94 records.
[HistorySynchronizer.swift:223] onBatchResult > Done with batched mirroring.
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item F2Lbj8Sepnf4 changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item UcDO59RcfZ_U changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item WgbWgraAsh7Y changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item 0yMrH5BMOPV_ changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item ady6ifRVfWWG changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item CffoLIehxm0S changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item dQL4ycN_Meaz changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item qGghCG7r4Xrp changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item UEofCU8u158P changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item ZiHby4Im-nUZ changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item 7zpHgnu1mxRq changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item mImDmL7F8n8P changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item RFlBblmWQAav changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item -2-GNt_nM55l changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item 1P2WXcLMF9-p changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item 3asx_XZn4Nal changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item 4BX15tE8pGcA changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item 4rtt5FbZ0Xaq changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item 5iNdOCd6NSGy changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item 8jEZTHjgG5W3 changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item CNjAtDGyRxLX changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item D27Xf8giDVY2 changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item e8VcN-OG_S2n changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item eoRRy9nQ6Tx9 changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:934] insertOrUpdatePlace(_:modified:) > Local changes overriding remote.
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item Jd0tn82OACNN changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item jyfO9bi3zIGH changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item K-kAHRn-EGnk changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item lPrVN2vd9TxY changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item lT_OMCF-7GBn changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item nGKVJOmSKTVp changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item p9Cx5uqVBzR1 changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item PJdOMZ2QcaIR changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item pnLZh-vsI3lc changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item RAc-ies0pb-F changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item RV5IfyNyLhEW changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item SAsAXPVgo6dr changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item VssvTRHHJoYT changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item wZR0DeYHtfij changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item B-T7H6UzvWTl changed both locally and remotely. Comparing timestamps from different clocks!
[SQLiteHistory.swift:932] insertOrUpdatePlace(_:modified:) > Warning: history item wsiuPQKP3mG2 changed both locally and remotely. Comparing timestamps from different clocks!
[Downloader.swift:192] handleSuccess > Advancing baseTimestamp to 1492878088080 - 1
[Downloader.swift:204] handleSuccess > Advancing lastModified to Optional(1492878088080) ?? 1492878088080.
[BrowserDB.swift:312] checkpoint() > Checkpointing a BrowserDB.
[SwiftData.swift:561] checkpoint > Running WAL checkpoint on /private/var/mobile/Containers/Shared/AppGroup/45E9BB41-F57E-4587-9C4F-090D90BBEAF9/profile.profile/browser.db on thread <NSThread: 0x170a61780>{number = 7, name = (null)}.
[SwiftData.swift:563] checkpoint > WAL checkpoint done on /private/var/mobile/Containers/Shared/AppGroup/45E9BB41-F57E-4587-9C4F-090D90BBEAF9/profile.profile/browser.db.
[HistorySynchronizer.swift:164] uploadOutgoingFromStorage(_:lastTimestamp:withServer:) > Uploading 0 deleted places.
[IndependentRecordSynchronizer.swift:88] uploadRecords(_:lastTimestamp:storageClient:onUpload:) > No modified records to upload.
[HistorySynchronizer.swift:166] uploadOutgoingFromStorage(_:lastTimestamp:withServer:) > MOOMOO Done Uploading deleted places
[SQLiteHistory.swift:995] getModifiedHistoryToUpload() > MOOMOO SQLiteHistory.getModifiedHistoryToUpload residentSize=Optional(128.703125)

When we go into getModifiedHistoryToUpload(), the app uses 128 MB.

We never get past executing the query. There is some logging right after runQuery() but that is never hit. So we run out of memory doing the big query.

Comment 4

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

Asking some guidance from :rnewman here about what a good strategy is to get past this. Also interested in an initial quick workaround that we can ship next week and a bigger story on how to improve this in general for large profiles. If possible.

Comment 6

[Richard Newman [:rnewman]]

My understanding of this situation is that the iOS device has decided that it has more history than the server, and needs to upload it.

This probably occurred when node-reassigned: if the iOS device gets there first, or desktop doesn't upload most of history, the iOS device will see thousands of local rows with `should_upload = 1`.

This code is not expecting to grab 50,000 rows, but it does so, and they all end up in memory before being batched for upload.


There are several solutions.

Option 1:
---
The most thorough is to use a SwiftData `LiveSQLiteCursor` instead of a `FilledArrayCursor`. `getModifiedHistoryToUpload` would become a wrapper around that cursor, rather than returning an array. This approach requires careful use of the SwiftData connection queue, so it might not be feasible -- we'd block other users of the DB.

An alternative is to open a brand new connection to the database, scoped to that operation. This is safer but more complex. (Our current design has a single connection and assumes that queries will be fast and asynchronous. Using a live cursor is, approximately, slow and synchronous!)
---

Option 2:
---
The other solution is to batch retrievals. We already batch records for upload in `uploadModifiedPlaces`, after Bug 1323373. This is happening one step before, when we fetch the records that we're about to batch.

As I understand it, the current code correctly uses XIUS to upload each batch, and correctly marks the uploaded records as synchronized after each batch.

That *should* mean it's perfectly safe to apply a limit to the inner part `getModifiedHistoryToUpload`. Simply applying a limit will make a small amount of progress on each sync. We could also apply a limit and try several times, making progress each time, or schedule a follow-up sync for a few seconds later, allowing this sync to complete.

Note that by default we checkpoint the WAL after this upload, so we might consider tweaking that heuristic.

A slightly more refined approach is to count the number of affected rows (which is a full table scan, but not a bad one), then decide on how many iterations are needed, and bound that number to avoid an overly long sync.

A final note: at present we retrieve by siteID, in order to collect visits. It's tempting to tweak the query to retrieve records by date descending, ensuring that we upload recent history first. This is admirable -- right now we'll probably upload your oldest history first! -- but careful testing is necessary if you do so.
---

I suggest Option 2: it doesn't involve touching SwiftData in order to achieve streaming, and it's possible that you can achieve a memory-bounded short-term solution simply by extracting the history retrieval part of the query and tacking a `LIMIT 1000` on it.

Comment 7

[Stephan Leroux [:sleroux]]

Attachment: Link to Github pull-request: https://github.com/mozilla-mobile/firefox-ios/pull/2661

Comment 8

[Stephan Leroux [:sleroux]]

Landed master 87045c54914bd3dca9c8fe1d95c56c35b8e3c27f, v7.x a120df87b45c41cf2a86569e8451aa87cf5f2d6f

Comment 9

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

I re-opened this because one tester still has a crasher in getModifiedHistoryToUpload. Our other tester got past it. We need to find the sweet spot for the limit and probably do a little bit of memory profiling. Hopefully this will be just a matter of tuning the query limits.

Comment 10

[Richard Newman [:rnewman]]

The likely culprit is the visit aggregation query:

        let historyLimit =
        "SELECT * FROM history " +
        "WHERE history.should_upload = 1 LIMIT ?"

        let sql =
        "SELECT " +
        "history.id AS siteID, history.guid AS guid, history.url AS url, history.title AS title, " +
        "v1.siteID AS siteID, v1.date AS visitDate, v1.type AS visitType " +
        "FROM " +
        "visits AS v1 " +
        "JOIN (\(historyLimit)) as history ON history.id = v1.siteID AND v1.type <> 0 " +
        "LEFT OUTER JOIN " +
        "visits AS v2 " +
        "ON v1.siteID = v2.siteID AND v1.date < v2.date " +
        "GROUP BY v1.date " +
        "HAVING COUNT(*) < ? " +
        "ORDER BY v1.siteID, v1.date DESC"

This query is tabular, so we'll accrue the URL and title up to 20 times for each history item.

The fix will be to split this into two queries. We'll find the history items we care about:

        let historyItems =
        "SELECT id, guid, url, title FROM history " +
        "WHERE should_upload = 1 LIMIT ?"

Run that, and collect the rows (`places[id] = Place(guid: guid, url: url, title: title)`) and IDs.

The cursor is dropped at this point, and only contains `limit` rows anyway.

Now use the IDs to retrieve visits, very similar to how we do it now (untested SQL):

        let historyIDs = "(123, 456, 789)"         // Construct this!
        let visitsQuery =
        "SELECT " +
        "v1.siteID AS siteID, v1.date AS visitDate, v1.type AS visitType " +
        "FROM " +
        "(SELECT * FROM visits WHERE siteID IN \(historyIDs) AND type <> 0) AS v1 " +
        "LEFT OUTER JOIN " +
        "visits AS v2 " +
        "ON v1.siteID = v2.siteID AND v1.date < v2.date " +
        "GROUP BY v1.date " +
        "HAVING COUNT(*) < ? " +
        "ORDER BY v1.siteID, v1.date DESC"

The results will be visits only, and we can accumulate them just as we do now, using the `siteID` to find the place.

Comment 11

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

Landed additional fix:

https://github.com/mozilla-mobile/firefox-ios/commit/66077a678df066059f294f3c7b3b9613ff783e8c

This only changes the limits, using lower number of history items:

        let args: Args = [
            50, // Limited number of history items to retrieve
            20  // Maximum number of visits to retrieve per history item
        ]

Of course this is not ideal, but it gets us past a crash short term. Let's file a new bug to optimize the implementation of SQLiteHistory.getModifiedHistoryToUpload and land that as part of 7.5 or 8.0.