Open Bug 1561467 Opened 1 year ago Updated 10 months ago

Slow merges with new bookmark sync

Categories

(Firefox :: Sync, defect, P3)

defect

Tracking

()

ASSIGNED

People

(Reporter: lina, Assigned: lina)

References

(Depends on 2 open bugs, Blocks 1 open bug)

Details

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}]}

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?
Assignee: nobody → lina
Status: NEW → ASSIGNED

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

For more information, please visit auto_nag documentation.

Flags: needinfo?(markh)

I'm working on this. :-)

Flags: needinfo?(markh)
Priority: -- → P1
Depends on: 1567238
Depends on: 1556459
Depends on: 1567242
Depends on: 1572615
Depends on: 1575757
Depends on: 1576796
Depends on: 1576810
  • 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
  • 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.

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!

Flags: needinfo?(CKOTTMozillaBugzilla)

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

Flags: needinfo?(CKOTTMozillaBugzilla)
Group: mozilla-employee-confidential

Uh, oops, unconfidentialling this one.

Group: mozilla-employee-confidential

We've harvested the low hanging fruit here!

Priority: P1 → P3
You need to log in before you can comment on or make changes to this bug.