1561467 - Slow merges with new bookmark sync

Status: NEW

(Firefox :: Sync, defect, P3)

Description

[Lina Butler [:lina]]

Looking through some of our shutdown hangs, I see several slow merges.

This one reaches notifyObservers, but takes almost 30 seconds to notify observers about changes. Then finalize is called, and probably hangs trying to close the database. apply takes about 8 seconds, which is okay—except the main Places connection can't write to the database at all during those 8 seconds, so new history visits and bookmark edit operations will queue up. Everything before applying is pretty snappy, though.

{"name":"SyncedBookmarksMirror: finalize","state":{"steps":[{"step":"fetchLocalTree","at":1561447646232},{"step":"fetchNewLocalContents","at":1561447646451},{"step":"fetchRemoteTree","at":1561447646453},{"step":"fetchNewRemoteContents","at":1561447646454},{"step":"merge","at":1561447646478},{"step":"apply","at":1561447653882},{"step":"notifyObservers","at":1561447653931},{"step":"finalize","at":1561447681207}]}

This one also reaches notifyObservers, but is a lot worse. fetchNewRemoteContents takes almost a minute. apply takes almost two minutes. notifyObservers takes ~18 seconds.

{"name":"SyncedBookmarksMirror: finalize","state":{"steps":[{"step":"fetchLocalTree","at":1561330688470},{"step":"fetchNewLocalContents","at":1561330688622},{"step":"fetchRemoteTree","at":1561330689495},{"step":"fetchNewRemoteContents","at":1561330745937},{"step":"merge","at":1561330746034},{"step":"apply","at":1561330860464},{"step":"notifyObservers","at":1561330878245},{"step":"finalize","at":1561330920179}]}

This one hangs on fetchNewRemoteContents, since the last step we record before finalize is fetchRemoteTree. fetchRemoteTree takes a little over 2 seconds, which is okay. Weirdly, everything from start to end is a little over 4 seconds, suggesting the call to this.db.close is hanging.

{"name":"SyncedBookmarksMirror: finalize","state":{"steps":[{"step":"fetchLocalTree","at":1561167691027},{"step":"fetchNewLocalContents","at":1561167691616},{"step":"fetchRemoteTree","at":1561167693790},{"step":"finalize","at":1561167695258}]}

This one has about a 2 second gap between fetchLocalTree and fetchRemoteTree, and a 3 minute gap between fetchRemoteTree and finalize, meaning fetchNewRemoteContents still didn't finish after 3 minutes.

{"name":"SyncedBookmarksMirror: finalize","state":{"steps":[{"step":"fetchLocalTree","at":1560958105596},{"step":"fetchNewLocalContents","at":1560958105864},{"step":"fetchRemoteTree","at":1560958107435},{"step":"finalize","at":1560958318288}]}

Comment 1

[Lina Butler [:lina]]

Questions I have:

• Why is fetchNewRemoteContents so slow?
• Can we speed up apply, maybe using temp tables instead of triggers on a view—or even multiple queries? IIRC, views can't use indexes, it's probably going to be expensive if we end up doing a full table scan on each merge. Now that we're merging directly in Rust, on the storage thread, we don't have to worry about mozIStorageAsyncStatements ping-ponging between the main and async threads, and crossing C++/JS.
• Can we use an interruptible read-only connection for notifyObservers? Or go all the way with bug 1556459?

Comment 2

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

The priority flag is not set for this bug.
:markh, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 3

[Lina Butler [:lina]]

I'm working on this. :-)

Comment 4

[CKOTTMozillaBugzilla]

• I've experienced severe slowdowns in sync performance for the past 2 days or so.
• I believe it started when my system updated to 70.0b1 (64-bit) (Dev channel).
• I just now bookmarked this page; the sync spinner animated for 30 seconds.
• I am not seeing this problem with Firefox 68.0.2 (64-bit) (Release channel).
• My system: Windows 10 Home, 64-bit, v1903, build 18362.295

Comment 5

[CKOTTMozillaBugzilla]

• Also, the (70.0b1 64-bit) UI freezes if I attempt to add or change a bookmark while the sync spinner is animating. I just confirmed that this is not the case with 68.0.2 64-bit.

Comment 6

[Lina Butler [:lina]]

Oooh, this is really useful feedback; thanks, CKOTTMozillaBugzilla! A couple of requests for you, if you have cycles to help debug:

• Please attach a recent Sync log from about:sync-log. Either success or error is fine, but one that has a bookmark sync. Bookmarking a page, forcing a sync, and attaching the log would also work! You may need to enable detailed logging.
• In about:support, please scroll down to "Places Database", click the "Verify Integrity" button, and copy-paste the output into this bug.

Thanks so much!

Comment 7

[CKOTTMozillaBugzilla]

Certainly. Could you please change this bug to "Mozilla Confidential" before I upload these logs?

Comment 8

[Thom Chiovoloni [:tcsc] (ex-moco)]

Uh, oops, unconfidentialling this one.

Comment 9

[Mark Hammond [:markh] [:mhammond]]

We've harvested the low hanging fruit here!