1433806 - Measure bookmark mirror performance

Status: RESOLVED FIXED

(Firefox :: Sync, enhancement, P2)

Description

[Lina Butler (ex-Mozilla)]

For a no-op sync, there's some jank when building the local tree and merging: https://perfht.ml/2Bz0jZu, https://perfht.ml/2Bz5qJb We can optimize this specific case in bug 1408092, but we'll still build a full tree if one or two bookmarks changed. I think we should at least periodically yield to the event loop in `fetch{Local, Remote}Tree`, as we do in `PlacesUtils.promiseBookmarkTree`, and maybe even in the merger.

We should also profile with differently shaped trees. Mine is large but shallow, with most bookmarks in the menu, and no more than two levels of nesting. For users with larger or deeper trees, the merger will likely behave differently.

Comment 1

[Lina Butler (ex-Mozilla)]

Morphing this into a general mirror perf bug. Please follow up here, nivtwig.

Comment 2

[nivtwig]

In reply to Kit Cambridge from Bug 1305563 comment 219

> If you haven't already, could you please enable "Debug" logging for
> about:sync-log (https://addons.mozilla.org/en-US/firefox/addon/about-sync/
> is easiest; it'll also give you validation results, which I'd be very
> curious to see for your full 35k tree), and paste the times here? (Side
> question: do you notice Firefox freezing or janking during the first sync at
> all?)

I did a second (or receiving) sync, not the first/sending/uploading sync. 

*) I see that Firefox writes to disk at 10-20MB per second for sustained periods of time, which is strange, and seems too much. Why does it need to write to disk so much? it seems it can amount to Gigabytes !

Task manager shows that the disk (an SSD) usage by what I think is the main Firefox process (not a content process by the command line parameters), was around 10-20MB/s for long periods of time. By looking at the "Performance" tab of Task manager, I could see that this was mostly Write Speed of the disk, not read speed, which was considerably less than that. The "Performance" tab shows the Read/Write speed per disk, not per process, but since I know that Firefox had this amount of disk usage (10-20 MB/s ), and other processes were not using that much, then it must be caused by the Firefox process.

*) I forgot to check rigorously whether Firefox freezes. However I used Firefox during some of this time and didn't notice Firefox freezing/janking during the Sync, but I used it only from time to time, not all the time. CPU usage was around 40-50% , caused mostly by the main Firefox process.

*) The "About Sync" add-on displays in Collections / Bookmarks / Summary : 
"42263 records (40035 deleted)"

Why does it keep the old ~40000 deleted bookmark records on the server after several syncs I did with only 2238 bookmarks (I assume it is on the server, not the local places database)? 
I deleted all bookmarks on the local computer's bookmarks menu when Sync was disconnected, and did several syncs before that got me the 2238 bookmarks, but it seems the server keeps the records of the whole ~40000 bookmarks although they were deleted long ago. Why ?

*) Here are the times from the log file :

> 1517760350975	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000
> 1517760351078	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760353563	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=1000
> 1517760353663	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760355866	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=2000
> 1517760355976	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760358148	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=3000
> 1517760358260	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760360890	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=4000
> 1517760360984	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760363895	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=5000
> 1517760363981	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760366893	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=6000
> 1517760366987	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760369398	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=7000
> 1517760369480	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760371917	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=8000
> 1517760372009	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760374192	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=9000
> 1517760374277	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760376298	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=10000
> 1517760376390	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760378470	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=11000
> 1517760378556	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760380734	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=12000
> 1517760380817	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760383501	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=13000
> 1517760383604	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760386135	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=14000
> 1517760386221	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760388206	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=15000
> 1517760388285	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760390506	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=16000
> 1517760390588	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760393282	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=17000
> 1517760393364	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760396335	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=18000
> 1517760396415	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760399719	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=19000
> 1517760399806	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760402512	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=20000
> 1517760402624	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760404756	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=21000
> 1517760404835	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760406638	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=22000
> 1517760406715	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760408568	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=23000
> 1517760408648	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760410599	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=24000
> 1517760410678	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760412956	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=25000
> 1517760413034	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760415317	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=26000
> 1517760415402	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760417650	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=27000
> 1517760417729	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760420022	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=28000
> 1517760420105	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760422375	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=29000
> 1517760422453	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760424744	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=30000
> 1517760424824	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760427297	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=31000
> 1517760427427	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760429958	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=32000
> 1517760430036	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760432340	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=33000
> 1517760432417	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760434469	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=34000
> 1517760434550	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760436611	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=35000
> 1517760436704	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760438785	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=36000
> 1517760438869	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760441166	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=37000
> 1517760441258	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760443565	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=38000
> 1517760443646	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760445949	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=39000
> 1517760446032	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760448352	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=40000
> 1517760448435	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760451019	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=41000
> 1517760451103	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517760452346	Sync.Collection	DEBUG	GET success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?full=1&sort=index&limit=1000&offset=42000
> 1517760911795	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
> 1517760912496	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
> 1517761109370	Sync.Engine.Bookmarks	INFO	Records: 42263 applied, 42263 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
> 1517761109383	Sync.Engine.Bookmarks.Mirror	DEBUG	Building remote tree from mirror
> 1517761109949	Sync.Telemetry	DEBUG	recording event: {"object":"mirror","method":"fetch","value":"remoteTree","extra":{"time":"566.1359902874101","count":"42263"}}
> 1517761109960	Sync.Engine.Bookmarks.Mirror	DEBUG	Building local tree from Places
> 1517761109983	Sync.Telemetry	DEBUG	recording event: {"object":"mirror","method":"fetch","value":"localTree","extra":{"time":"22.842491006711498","count":"21"}}
> 1517761109984	Sync.Engine.Bookmarks.Mirror	DEBUG	Fetching content info for new mirror items
> 1517761110071	Sync.Telemetry	DEBUG	recording event: {"object":"mirror","method":"fetch","value":"newRemoteContents","extra":{"time":"85.88607706292532","count":"2207"}}
> 1517761110071	Sync.Engine.Bookmarks.Mirror	DEBUG	Fetching content info for new Places items
> 1517761110073	Sync.Telemetry	DEBUG	recording event: {"object":"mirror","method":"fetch","value":"newLocalContents","extra":{"time":"2.0282256067730486","count":"7"}}
> 1517761110074	Sync.Engine.Bookmarks.Mirror	DEBUG	Building complete merged tree
> 1517761110127	Sync.Telemetry	DEBUG	recording event: {"object":"mirror","method":"merge","value":"structure","extra":{"type":"new"}}
> 1517761110160	Sync.Engine.Bookmarks.Mirror	DEBUG	Applying merged tree
> 1517761110171	Sync.Engine.Bookmarks.Mirror	DEBUG	Setting up merge states table
> 1517761110290	Sync.Engine.Bookmarks.Mirror	DEBUG	Rewriting tag queries in mirror
> 1517761110300	Sync.Engine.Bookmarks.Mirror	DEBUG	Inserting new URLs into Places
> 1517761111039	Sync.Engine.Bookmarks.Mirror	DEBUG	Updating value states for local bookmarks
> 1517761111304	Sync.Engine.Bookmarks.Mirror	DEBUG	Updating structure states for local bookmarks
> 1517761111328	Sync.Engine.Bookmarks.Mirror	DEBUG	Removing remotely deleted items from Places
> 1517761111912	Sync.Engine.Bookmarks.Mirror	DEBUG	Flagging remotely deleted items as merged
> 1517761111912	Sync.Engine.Bookmarks.Mirror	DEBUG	Recording observer notifications
> 1517761111913	Sync.Engine.Bookmarks.Mirror	DEBUG	Recording observer notifications for removed items
> 1517761111913	Sync.Engine.Bookmarks.Mirror	DEBUG	Recording observer notifications for changed GUIDs
> 1517761111916	Sync.Engine.Bookmarks.Mirror	DEBUG	Recording observer notifications for new items
> 1517761112461	Sync.Engine.Bookmarks.Mirror	DEBUG	Recording observer notifications for moved items
> 1517761112463	Sync.Engine.Bookmarks.Mirror	DEBUG	Recording observer notifications for changed items
> 1517761112464	Sync.Engine.Bookmarks.Mirror	DEBUG	Recording observer notifications for changed annos
> 1517761112464	Sync.Engine.Bookmarks.Mirror	DEBUG	Recording notifications for changed keywords
> 1517761112465	Sync.Engine.Bookmarks.Mirror	DEBUG	Staging locally changed items for upload
> 1517761112956	Sync.Engine.Bookmarks.Mirror	DEBUG	Fetching records for local items to upload
> 1517761112977	Sync.Engine.Bookmarks.Mirror	DEBUG	Replaying recorded observer notifications
> 1517761112977	Sync.Engine.Bookmarks.Mirror	DEBUG	Notifying bookmark observers
> 1517761116046	Sync.Engine.Bookmarks.Mirror	DEBUG	Notifying anno observers
> 1517761116964	Sync.Engine.Bookmarks	INFO	Posting 21 records of 10175 bytes with batch=true
> 1517761116966	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
> 1517761116967	Sync.Collection	DEBUG	POST Length: 10175
> 1517761118959	Sync.Collection	DEBUG	POST success 200 https://sync-440-us-west-2.sync.services.mozilla.com/1.5/63098287/storage/bookmarks?batch=true&commit=true
> 1517761119482	Sync.Engine.Bookmarks.BookmarkSyncUtils	WARN	Trying to remove non-existent mobile query
> 1517761119503	Sync.Engine.Bookmarks.BookmarkSyncUtils	DEBUG	pushChanges: Processed change records: {"weak":0,"skipped":0,"updated":21}
> 1517761119510	Sync.Doctor	INFO	Skipping validation of bookmarks: Probability threshold not met
> 1517761119510	Sync.Doctor	INFO	Skipping validation: no engines qualify
> 1517761119512	Sync.Doctor	INFO	bookmarks reparier did not advance.
> 1517761119514	Sync.Status	DEBUG	Status.sync: success.sync => success.sync
> 1517761119514	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
> 1517761119516	Sync.Synchronizer	INFO	Sync completed at 2018-02-04 18:18:39 after 773.31 secs.
> 1517761119517	Sync.Declined	DEBUG	Handling remote declined: ["forms","history","passwords","prefs","addons","tabs"]
> 1517761119518	Sync.Declined	DEBUG	Handling local declined: []
> 1517761119518	Sync.Declined	DEBUG	Declined changed? false
> 1517761119522	Sync.Service	INFO	No change to declined engines. Not reuploading meta/global.
> 1517761119524	Sync.SyncScheduler	DEBUG	Next sync in 90000 ms. (why=schedule)

As you can see, the fetch seems to get too many records, it gets ~40000 bookmark records, instead of the actual non-deleted 2238. This is probably the reason for why my timings are much slower than yours. Is it really necessary?

The GET commands take about 102 seconds (assuming the numbers/times are in milliseconds )

But after that it takes 657s for the 3 lines until the following line :
> 1517761109370	Sync.Engine.Bookmarks	INFO	Records: 42263 applied, 42263 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.

The rest is only about 9s

Comment 3

[Lina Butler (ex-Mozilla)]

(In reply to nivtwig from comment #2)
> I see that Firefox writes to disk at 10-20MB per second for sustained periods of time, which is strange, and seems too much. Why does it need to write to disk so much? it seems it can amount to Gigabytes !

I don't know enough about this to offer a good answer, but I know it's an issue. Bug 1304389 and bug 973888 might be interesting. My top 5 contenders for sustained heavy writes are cookies, session store, Places and favicons, prefs, and telemetry, but that's based only on my intuition.

> Why does it keep the old ~40000 deleted bookmark records on the server after several syncs I did with only 2238 bookmarks (I assume it is on the server, not the local places database)?

Those are tombstones, markers stored on the sync server to indicate that a bookmark was removed. Tombstone records look like `{ id: "NAtB2WYVboB5", deleted: true }`; they don't store any content from the removed bookmark.

We represent deletions this way because Sync operates on individual records, and always advances and queries the server for new records that changed since the last sync time. If we issued hard DELETEs for removed bookmarks, instead of replacing them with tombstones, other clients wouldn't see the deletions as new changes. You can imagine better ways to design this protocol, of course, but that's the fun of working with a legacy system. :-P

Newly connected clients don't make use of those tombstones today, so I agree it's wasteful...and, because they're encrypted and completely opaque to the server, there's no way for us to filter them out when downloading records. This is changing in bug 1343103; we'll start storing tombstones, to avoid resurrecting items when the server is wiped and a device that didn't see all deletions wins the race to upload first.

> I deleted all bookmarks on the local computer's bookmarks menu when Sync was disconnected, and did several syncs before that got me the 2238 bookmarks, but it seems the server keeps the records of the whole ~40000 bookmarks although they were deleted long ago.

Oh, I see. Disconnecting should have removed those tombstones locally (and reset the sync flags for all bookmarks, so deleting while you're disconnected shouldn't write tombstones for them in the first place. However, if they're already on the server, they'll be downloaded again on the first sync after reconnecting, as you discovered).

It's possible Sync's "reset on disconnect" logic didn't run earlier. IIRC, disabling and re-enabling bookmark syncing in about:preferences#sync will wipe the server and clear out those old tombstones.

Comment 4

[nivtwig]

(In reply to Kit Cambridge (they/them) [:kitcambridge] from comment #3)
You didn't refer in your comment to the times from comment 2, and whether they can be improved.
For 2238 bookmarks (although there are ~40000 deleted bookmarks tombstones) it takes around ~13 minutes to sync, which is too much. 
Can something be done to improve the following :

*) The 657s (11 minutes) for what I think is inserting to the mirror.
Is that Bug 1435588 ? 
If true, a dependency should be added on this bug, and can you raise the priority of Bug 1435588 to P1 since it shows up probably as taking most of the operation time here, when there are large bookmark sets on the server that are copied to the mirror (11 minutes) ?

*) Why does the GET commands take 102 seconds (2 minutes), can this be improved ?
Why are they split to chunks of 1000? 
Wouldn't getting the full bookmarks from the server at once be faster instead of with multiple requests?
If that is done to prevent browser freezes, can't it be done async instead ?

Comment 5

[Lina Butler (ex-Mozilla)]

(In reply to nivtwig from comment #4)
> You didn't refer in your comment to the times from comment 2, and whether they can be improved.
> For 2238 bookmarks (although there are ~40000 deleted bookmarks tombstones)

Of course they can be improved. :-) It's worth pointing out that you still have 40k records total. It doesn't make a difference that most of them are tombstones, and that they're not going to be useful to a client syncing for the first time today. We have to fetch and store all of them, so you'll end up paying the cost of having all 40k, even if you only have 2k actual bookmarks. Changing that requires changes to the sync protocol, which is a longer-term effort. But, as you point out, we can cut this time down with bug 1435588.

> *) The 657s (11 minutes) for what I think is inserting to the mirror.
> Is that Bug 1435588 ? 

Yes. Once someone from our team takes it, we'll bump the priority to P1. It'll likely be later in the week, sadly; we're all busy with other work.

> *) Why does the GET commands take 102 seconds (2 minutes), can this be
> improved ?
> Why are they split to chunks of 1000?

There are a couple of reasons why we do this.

1. We don't want to hammer the server. Reading a large number of records is expensive; if the server is overloaded, we can give it a chance to service other requests, and tell us to back off.
2. If the sync is interrupted, at least we can make progress and write some records into the mirror. (For bookmarks, at least; for other types of records, we write directly into the store, which is slower). It's a drain on the server, and busy work for the client, to request everything, get interrupted because you closed Firefox or your laptop lid, and start over again from the beginning on the next sync.

Comment 6

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

For 10k bookmark tree sizes.

1. New profile (profile 0): Generate big random-ish tree, upload to fresh account https://perf-html.io/public/dcc9962a42f4af8200851d0d4beb95361fcea106/marker-chart/?hiddenThreads=1-2-3-4-5&thread=0&threadOrder=0-2-3-4-5-1&v=3 (Bookmark sync is around 40s-50s for 10k bookmarks up).
2. New profile (profile 1): Connect to same account and sync: https://perfht.ml/2pHekQO (Bookmark sync is around 50-60s for 10k bookmarks down).
3. New profile (profile 2): Create another large tree. Sync to same account: https://perfht.ml/2I4YMxY (Bookmark sync is about 80s for 10k up and 10k down).
4. Open profile 1 (from step 2) and sync: https://perfht.ml/2pIotg9 (40s, 10k bookmarks down, 0 up, 10k present in both locations).
5. New profile (profile 3): Create another tree, sync to same account: https://perfht.ml/2GtGDwo (100 of bookmark sync for 20k down, 10k up).
6. Open profile 0 (original profile), and sync: https://perfht.ml/2pGUaGP (~60s for 20k down, 10k present)

All of these times are improved from the previous engine, most of them are spent executing sql. It's not at all clear that we can optimize these queries without sacrificing correctness or robustness.

I'll attempt to get back to this later today with larger bookmark sizes. It seems this takes long enough that profiling a sync over this time span is unreliable, and causes crashes when exporting the profile.

Comment 7

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

Larger bookmark sizes push the ability of the gecko profiler past it's limit, I'm going to resolve this as done since the profiles above are sufficiently convincing that the mirror has improved performance.