Fenix took 10 full minutes to sync my history collection

[rfk]

I have an install of Firefox Beta on my phone that I hadn't used in a while, but I recently wanted to use it for some debugging. It was still connected to my account, so on launching the app for the first time in several weeks, it had do a large sync in order to catch up to the other clients. The sync worked very well, but it took a surprisingly long time - fully ten minutes to sync the history collection, according to adb logs.

Is it expected that we should take this long to sync a collection? I'm on a Galaxy S8, so not the newest of phones, but no slouch.

I've uploaded a snippet of my adb logcat info here

• basically all the log lines with "sync" or "places" in them, from the time history started syncing to the time it finished, starting at 18:05 and ending at 18:15. Some initial observations:
• It tries to download 5000 history entries, which I guess is expected for a device that's been offline for several weeks.
• It fetches the items from the server fairly quickly.
• It then logs 529 instances of ChunkedCoopTransaction commiting after taking allocated time, taking 10 minutes to write out the changes to disk.
• It also shows that browser autocomplete queries work and return quickly while this is happening, which is very nice!
• After applying the items, it tries to upload some items of its own, but fails with a 412 Precondition Failed. Which fair enough, it's likely that another client wrote to the history collection in those 10 minutes.

Everything worked here as far as I can tell, I'm just really surprised it took such a long time.

┆Issue is synchronized with this Jira Task
┆Epic: Important backlog

[rfk]

Poking around in the code a bit, I guess the apply_synced_visits method does do a fair amount of work for each history item pulled down from sync:

• Look up the DELETION_HIGH_WATER_MARK_META_KEY.
• Look up the corresponding PageInfo.
  • Create a new one if it doesn't exist.
  • Maybe update the guid if it does.
• Look up visits that may need to be skipped (which is a single db query, but a UNION of two separate tables).
• For each non-skipped visit:
  • Individualy insert it into moz_historyvisits.
  • Delete any existing tombstones for that visit.
• Update the frecency for that page, which involves:
  • Lookup info about the page
  • Score the recent visits (a three-way join of moz_historyvisits to itself)
  • Unconditionally write the result back to the db
• Update the page sync-change-counter and title.

If I've understood correctly, then that's comfortably 10+ db statements executed per item pulled down from sync, repeated for 5000 items in my case. Maybe taking 10 minutes is not so surprising after all 😆.

[mhammond]

Yeah, I'm not that surprised - but I bet there's some low hanging fruit. I don't think we've ever done even rudimentary profiling, or had a good look the query plans (we did have a cursory look at the plans long long ago)

[mhammond]

Moved to bugzilla: https://bugzilla.mozilla.org/show_bug.cgi?id=1865179

Change performed by the Move to Bugzilla add-on.