1392122 - Firefox stalls every time a bookmark is saved if “bookmarks“ is active in sync (with iPhone)panel

Status: RESOLVED WORKSFORME

(Firefox :: Sync, defect)

Description

[va]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.9; rv:55.0) Gecko/20100101 Firefox/55.0
Build ID: 20170814073321

Steps to reproduce:

In Firefox I have been collecting hundreds of bookmarks organized by topic in tens of folders and subfolders in the bookmarks menu. In the Preferences > Sync panel “Bookmarks” is active. If bookmarks is not selected, the bug does not manifest. This is reproducible.


Actual results:

Every time I save a new bookmark FireFox stalls for 10-15 seconds. 

A collateral unwanted effect is, if the Bookmark panel is open and I go on moving the mouse/the cursor, this can move subfolders around without me being able to control what where was moved. 


Expected results:

Expected is that FF saves a bookmark instantly and browsing can continue. 

Accidental mouse movements are not expected to move folders in the Bookmarks panel around.

Comment 1

[va]

This was not always the case. It has started happening many versions ago (before Mozilla switched to the monthly version-numbering system) ans has not improved (nor worsened) with any update. The stalling delay is also constant – cca 10-15 seconds.

Comment 2

[va]

This was not always the case. It has started happening many versions ago (before Mozilla switched to the monthly version-numbering system) ans has not improved (nor worsened) with any update. The stalling delay is also constant – cca 10-15 seconds.

Comment 3

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

Would it be possible for you to follow the instructions at https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug and enable "success logging", then reproduce the issue and upload any new logs created? The timestamps in the log files might be able to give us a clue as to what is going on. Also, could you give a rough estimate of how many bookmarks you have in total (ie, are we talking "a few hundred", "around a thousand", "a few thousand" etc)?

Comment 4

[va]

Attachment: bugzilly ƒ.zip contains the requested logs (I hope)

Comment 5

[va]

Indeed I have perhaps a few hundred (sub)folders with a few thousand bookmarks – collected over ten years or so and seldom trimmed… :-\

Comment 6

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

The logs show a problem:

> 2017-08-22 07:47:23.154000 (10:38:00.246)	Sync.Telemetry	TRACE	observed weave:engine:sync:start bookmarks
> 2017-08-22 07:47:23.313000 (10:38:00.405)	Sync.Engine.Bookmarks	INFO	4 outgoing items pre-reconciliation
> 2017-08-22 07:47:23.315000 (10:38:00.407)	Sync.Engine.Bookmarks	INFO	Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
> 2017-08-22 07:47:23.315000 (10:38:00.407)	Sync.Telemetry	TRACE	observed weave:engine:sync:applied bookmarks
> 2017-08-22 07:47:51.181000 (10:38:28.273)	Sync.Engine.Bookmarks	INFO	Posting 4 records of 3441 bytes with batch=true

Note a 28 second gap between the last 2 lines. Kit, do you have any guesses what this might be? The fact it is jank *might* point at tags/annotations, which IIUC are still sync APIs.

va, do you use bookmark annotations or tags or any other feature heavily?

Comment 7

[va]

no, just simple bookmarking (I tried the feature a few times, found it useless for me and gave up using it). 

And the delay appears ONLY if bookmark synchronizing is active.

I have an addon named “Add Bookmark Here” (marked after the last update as “legacy”).

Comment 8

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

va, I meant to say this yesterday, but could you please try running Firefox in "Safe Mode" and see if the problem persists?

Comment 9

[va]

yes, also in safe mode the same delay of 10-20 seconds a few seconds after saving a bookmark.

Comment 10

[va]

excuse me: thought I'd started in Safe Mode but hadn't. And yes, in SM the delay persists and is even longer. Also, whatever I do with the mouse is executed a few seconds later, out of my control.

Comment 11

[Lina Butler [:lina]]

It's interesting that the 28 second gap appears *after* we've applied everything, but *before* we upload. It's possible tags are involved, since we still use the synchronous API to fetch them (https://searchfox.org/mozilla-central/rev/f2a1911ad310bf8651f342d719e4f4ca0a7b9bfb/toolkit/components/places/PlacesSyncUtils.jsm#1838-1839). That said, other parts of the UI like the Library and "Edit Bookmark" overlay also call `getTagsForURI`, so I'd expect those to be unresponsive, too. It would be great to see which queries we're executing during the sync, and if one of those is causing the hang.

va, could I trouble you to enable mozStorage logging using the instructions in bug 1388584, comment 23 and https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging#Mac_OS_X? `MOZ_LOG=timestamp,mozStorage:5` should do the trick. Those queries will likely contain private info like bookmark titles and URLs; we can mark this bug as confidential so that the logs are only accessible to Mozilla staff, or you can email them directly to me.

Comment 12

[va]

curiously, after enabling logging the delay did not occur anymore… Otherwise it is: save bookmark here (ca 10 seconds delay where the Mac works) > ca 20 secs stalling > then work again.

Comment 13

[Lina Butler [:lina]]

I'm now wondering if this is the same problem as bug 1405656 and bug 1339390.

We know `reorder` takes a long time for folders with many bookmarks, but maybe a tree with several hundred bookmarks, spread out across multiple folders, is sufficient to cause issues. If you have time to help us debug, I'd still like to see the storage logs, even if the delay goes away. The queries we're running might give me some clues about where we're getting stuck.

If you'd like to dig deeper, you could try creating a fresh Firefox profile (https://support.mozilla.org/en-US/kb/profile-manager-create-and-remove-firefox-profiles#w_creating-a-profile), signing in with your existing Sync account, letting it finish downloading and applying your bookmarks, and seeing if you can still reproduce the hang. If that works without hanging, try creating a fresh profile, restore the latest backup from the `bookmarkbackups` folder in your current profile, create a new, throwaway Sync account, and see if reordering hangs.

If you can't repro in a fresh profile, or with a fresh account, you might try running the Places Maintenance add-on in your main profile (https://addons.mozilla.org/en-US/firefox/addon/places-maintenance/), and seeing if the hang goes away. Maintenance fixes up the schema and vacuums the DB.

As a last resort, you could also email me the places.sqlite file from your main profile, so that I can do some debugging. (It contains all your bookmarks and history, so it's totally OK if you don't want to do this). I can also try to come up with some SQL queries for you to run, either directly on the database, or via the About Sync add-on. In particular, I'd be interested in seeing the query plan for reordering.

Comment 14

[va]

Hello and thank you for caring and please excuse my delayed reply. 

I am an experienced Mac user, but have 0,01 programming knowledge and have had little time an patience lately :-) I would prefer not to experiment with profiles, what you describe would take me a couple of hours. If you tell me how, I can do a search in the SQlite database for you, if this may help. 

The delay did NOT go away after all. THe Places Maintenance addon seems to have a temporary effect. The two bugs you mention sound similar, why did it take so many versions until s-o complained? Perhaps not many users retain so many bookmarks in such complex folder-trees (I've been doing this for years, and – by the way: I still miss a search-function restricted to my own bookmarks… Probably for the same rweason, noone does this!). 

Deleting one of the live-bookmarks folders (those with the three increasing quarter-circles symbol in their icon) then pressing Undo also causes a delay (reordering?). I only have nine, in a subfolder to keep them out of the way; and 10-15 bookmarks in each. The recently Bookmarked and Recent Tags folders cannot be deleted, they come back automatically?.

Finally: I had to downgrade to FF 55.0.3 because one of my favorite “legacy” extensions, https://addons.mozilla.org/en-US/firefox/addon/add-bookmark-here-2/ does not work in the next version. This addon might play some role in the delay bug.

Comment 15

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

Sorry for the delay in getting back to you, but there's not a whole lot we can do on Firefox 55, and we've done lots of work in the meantime that may mean this bug no longer exists.

va, if you still have this problem on a release version of Firefox, please reopen the bug and we'll see if we can reproduce it.

Comment 16

[va]

Hello Mark and everybody else, thank you. As soon as I can update FF I'll get back if the bug is still present.