1303831 - v48.0.2 sync problem but not Fx47 - 2 users

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P1)

Description

[FredMcD]

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:46.0) Gecko/20100101 Firefox/46.0
Build ID: 20160502172042

Steps to reproduce:

https://support.mozilla.org/en-US/questions/1139318
Bookmarks painfully slow after 48.0.2 Firefox update

Disable sync ends problem

Master Password issue also.



Actual results:

https://support.mozilla.org/en-US/questions/1139318#answer-918240

To summarize my observations, v48.0.2 is very slow during bookmark editing and saving. Just pressing the star usually works ok. The problem does not yet occur in v47.0. I don't know whether it's already present in v48.0. In 48.0.2 it does not present itself when the master password is not yet entered (this still surprises me) or if sync is turned off overall or turned off for bookmarks. So the going hypothesis is that 48.0.2 bookmarking has acquired problems interacting with the sync feature and if sync is on, it causes interference that significantly slows down bookmarking to a level annoying to use.

Comment 1

[Loic]

I think you have to download and use the tool mozregression to find a regression range in FF48, espcially if it's reproducible only on a few machines.
See http://mozilla.github.io/mozregression/ for details.

In addition, could you attach the "graphics" section from about:support, please.

Comment 2

[FredMcD]

I asked the user https://support.mozilla.org/en-US/user/jasu
to post the information here.

Comment 3

[Lina Butler [:lina]]

Mark will keep looking at jank.

Comment 4

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

So _buildGUIDMap(), since it was changed to use promiseBookmarksTree etc is janky, even though it doesn't appear to be reported as janky by PerformanceStats.jsm. That patch first landed in 48, so I suspect is the problem here.

In my test profile I have 10k bookmarks. I start a first sync for bookmarks, and before it actually starts, I pull down the "File" menu. In the log, I see the GUID map being built with log lines like:

> 1479187975419	Sync.Engine.Bookmarks	TRACE	Preparing 10026 outgoing records
> 1479187977786	Sync.Engine.Bookmarks	TRACE	Mapped: ,fBookmarks Menu,menu,false
> 1479187977787	Sync.Engine.Bookmarks	TRACE	Mapped: Bookmarks Menu,qRecentTags,xUTNzeJdBR79,false

As soon as they appear, I press "x" to exit the app. However, the menu doesn't change or start a shutdown until *all* bookmarks have been reported via a "Mapped: " line. The sync "spinner" also stalls for this time - IOW, the browser appears unresponsive and menus don't work.

With the patch I'm about to upload, things work much better - the menu responds immediately and the "Mapped: " lines stop immediately, and we start doing the normal shutdown via abort. So in effect, this patch is solving 2 problems: starving the event-loop causing jank, and correctly aborting due to shutdown. I can't measure a performance difference before and after this patch (in all cases I get ~3.5 seconds, with the noise between runs drowning out the change), and in either case, the 3.5 seconds is dwarfed by the many minutes the sync itself takes if it isn't interrupted.

Patch forthcoming - I'll ask both Thom and Richard to have a look...

Comment 5

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

Attachment: Bug 1303831 - have _buildGUIDMap yield to the event loop and have it abort on shutdown.

Review commit: https://reviewboard.mozilla.org/r/93040/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/93040/

Comment 6

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

Comment on attachment 8810729 [details]
Bug 1303831 - have _buildGUIDMap yield to the event loop and have it abort on shutdown.

https://reviewboard.mozilla.org/r/93040/#review93132

Looks good with nit below addressed (assuming I'm not mistaken with it).

::: services/sync/modules/engines/bookmarks.js:306
(Diff revision 1)
>            yield [tree, parent];
>          }
>          if (tree.children) {
>            for (let child of tree.children) {
> +            store._sleep(0);
> +            Async.checkAppReady(); // avoid long loops after shutdown.

Isn't this implicit in the use of `_sleep`, which spins an event loop? I think our event loops explicitly check for shutdown [here](https://dxr.mozilla.org/mozilla-central/source/services/common/async.js#97).

There's probably some argument to be made that the explicit `checkAppReady` call has the benefit of, well, being explicit. But I think a comment would be better for that purpose.

Comment 7

[Richard Newman [:rnewman]]

Comment on attachment 8810729 [details]
Bug 1303831 - have _buildGUIDMap yield to the event loop and have it abort on shutdown.

https://reviewboard.mozilla.org/r/93040/#review93140

guidmap needs to die. :/

::: services/sync/modules/engines/bookmarks.js:305
(Diff revision 1)
>          if (parent) {
>            yield [tree, parent];
>          }
>          if (tree.children) {
>            for (let child of tree.children) {
> +            store._sleep(0);

I'm not super familiar with walkBookmarksTree, but: if these children are all computed at once (fetched from the DB in one query), it's more efficient and perhaps a little  safer/more consistent to only sleep outside this little loop. That is, yield each time we process a folder, not each time we process a child.

Give that a shot, see if it's still responsive?

Comment 8

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

(In reply to Richard Newman [:rnewman] from comment #7)
> I'm not super familiar with walkBookmarksTree, but: if these children are
> all computed at once (fetched from the DB in one query),

Yes, they're all grabbed at once from the promiseBookmarksTree call. My only hesitation with sleeping for each folder would be that it doesn't seem that uncommon to have lots of children in e.g. unfiled. If you have 3000 top-level items in unfiled, this patch probably won't make it any more responsive.

The ideal solution would probably be to do it every N bookmarks instead of based on your folder structure...

Comment 9

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

(In reply to Thom Chiovoloni [:tcsc] from comment #6)
> Isn't this implicit in the use of `_sleep`, which spins an event loop? I
> think our event loops explicitly check for shutdown

Ah yes, good spot. I just removed the checkAppReady() call.

(In reply to Thom Chiovoloni [:tcsc] from comment #8)
> uncommon to have lots of children in e.g. unfiled. If you have 3000
> top-level items in unfiled, this patch probably won't make it any more
> responsive.

Yeah - in my test profile I have 10k bookmarks in a single folder, so doing it per folder instead of per child still shows the issue.

> The ideal solution would probably be to do it every N bookmarks instead of
> based on your folder structure...

Yeah, I was going to do that, but I can't measure a performance loss here - any differences is within the noise from each run - so I'm just going to land it with the _sleep() as initially placed.

Thanks!

Comment 10

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

Comment on attachment 8810729 [details]
Bug 1303831 - have _buildGUIDMap yield to the event loop and have it abort on shutdown.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/93040/diff/1-2/

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0ecd90195aa2
have _buildGUIDMap yield to the event loop and have it abort on shutdown. r=rnewman,tcsc

Comment 12

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/0ecd90195aa2

Comment 13

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

Comment on attachment 8810729 [details]
Bug 1303831 - have _buildGUIDMap yield to the event loop and have it abort on shutdown.

Approval Request Comment
[Feature/regressing bug #]: bug 1008592
[User impact if declined]: Browser may be janky and unresponsive for a short period while syncing bookmarks
[Describe test coverage new/current, TreeHerder]: Existing tests pass
[Risks and why]: Very low risk patch limited to bookmark syncing
[String/UUID change made/needed]: None

Comment 14

[Gerry Chang [:gchang]]

Comment on attachment 8810729 [details]
Bug 1303831 - have _buildGUIDMap yield to the event loop and have it abort on shutdown.

Fix an issue related to bookmark syncing. Beta51+ and Aurora52+. Should be in 51 beta 2.

Comment 15

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/b557b0081e7c

Comment 16

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-beta/rev/ca83246bd45f

Comment 17

[Petruta Horea [:phorea], Desktop QA]

I couldn't reproduce the initial issue even if I used several methods and a profile with more than 10k bookmarks.

Fred, could you please try to reach out to the reporter and ask him to verify the fix on at least one build where it landed (51, 52, 53), eg 51 beta 2 [1].

Thank you!

[1] https://archive.mozilla.org/pub/firefox/candidates/51.0b2-candidates/build1/win32/en-US/

Comment 18

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

With 10k bookmarks, the STR for me are:

* ensure logging is visible - .dump prefs might be helpful - https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug
* arrange for a sync to upload all 10k bookmarks - eg, disable bookmark engine, sync, enable bookmark engine, sync.
* look for log messages and symptoms as described in comment 4.

Comment 19

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

(In reply to Mark Hammond [:markh] from comment #18)
> https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug

oops - that's not helpful re logging :( Set pref "services.sync.log.appender.dump" to "Debug" or "Trace", ensure you can see dump() calls in your console (eg, set "browser.dom.window.dump.enabled" to true and run Firefox from a console), and you should see sync logging in that console.

Comment 20

[FredMcD]

Original poster; https://support.mozilla.org/en-US/user/jasu

Other poster; https://support.mozilla.org/en-US/user/ChristopheB

I sent each a private message.

Comment 21

[Jason]

Hi Fred, I saw your message. Since I'm a total noob to this, you'd have to walk me through what you need me to do. If can do it in the few minutes after coming home from work and before sleep, I'm ready. All the best

Comment 22

[Petruta Horea [:phorea], Desktop QA]

Thank you Mark! Unfortunately I couldn't reproduce the issue with your steps using debug builds under Win 10 64-bit. I will try again on a different OS.

Jason, please use the below build and see if the issue is now fixed for you:
https://archive.mozilla.org/pub/firefox/candidates/51.0b3-candidates/build1/win32/en-US/
Thank you!

Comment 24

[Petruta Horea [:phorea], Desktop QA]

Marking as verified on Firefox 51 beta based on https://bugzilla.mozilla.org/show_bug.cgi?id=1301917#c9.