v48.0.2 sync problem but not Fx47 - 2 users

RESOLVED FIXED in Firefox 51

Status

()

Firefox
Sync
P1
normal
RESOLVED FIXED
a year ago
a year ago

People

(Reporter: FredMcD, Assigned: markh, NeedInfo)

Tracking

(Blocks: 1 bug)

46 Branch
Firefox 53
Points:
---

Firefox Tracking Flags

(firefox50 wontfix, firefox51 verified, firefox52 fixed, firefox53 fixed)

Details

(Whiteboard: [gfx-noted])

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(1 attachment)

(Reporter)

Description

a year ago
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

a year ago
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.
Component: Untriaged → Graphics
Flags: needinfo?(FredMcD)
Keywords: regressionwindow-wanted
Product: Firefox → Core
(Reporter)

Comment 2

a year ago
I asked the user https://support.mozilla.org/en-US/user/jasu
to post the information here.
Flags: needinfo?(FredMcD)
Component: Graphics → Bookmarks & History
Product: Core → Firefox
Whiteboard: [gfx-noted]
Component: Bookmarks & History → Sync
Mark will keep looking at jank.
Flags: needinfo?(markh)
(Assignee)

Comment 4

a year ago
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...
Flags: needinfo?(markh)
Comment hidden (mozreview-request)
(Assignee)

Updated

a year ago
Assignee: nobody → markh
Status: UNCONFIRMED → NEW
status-firefox50: --- → wontfix
status-firefox51: --- → affected
status-firefox52: --- → affected
status-firefox53: --- → affected
Ever confirmed: true
Keywords: regressionwindow-wanted
Priority: -- → P1

Comment 6

a year ago
mozreview-review
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.
Attachment #8810729 - Flags: review?(tchiovoloni) → review+

Comment 7

a year ago
mozreview-review
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?
Attachment #8810729 - Flags: review?(rnewman) → review+
(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...
(Assignee)

Comment 9

a year ago
(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 hidden (mozreview-request)

Comment 11

a year ago
Pushed by mhammond@skippinet.com.au:
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

a year ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/0ecd90195aa2
Status: NEW → RESOLVED
Last Resolved: a year ago
status-firefox53: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 53
(Assignee)

Comment 13

a year ago
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
Attachment #8810729 - Flags: approval-mozilla-beta?
Attachment #8810729 - Flags: approval-mozilla-aurora?
Flags: qe-verify+
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.
Attachment #8810729 - Flags: approval-mozilla-beta?
Attachment #8810729 - Flags: approval-mozilla-beta+
Attachment #8810729 - Flags: approval-mozilla-aurora?
Attachment #8810729 - Flags: approval-mozilla-aurora+

Comment 15

a year ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-aurora/rev/b557b0081e7c
status-firefox52: affected → fixed

Comment 16

a year ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-beta/rev/ca83246bd45f
status-firefox51: affected → fixed
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/
Flags: needinfo?(FredMcD)
(Assignee)

Comment 18

a year ago
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.
Flags: needinfo?(FredMcD) → needinfo?(petruta.rasa)
(Assignee)

Comment 19

a year ago
(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.
(Reporter)

Comment 20

a year ago
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

a year ago
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
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!
Flags: needinfo?(petruta.rasa) → needinfo?(jaregi)
(Assignee)

Updated

a year ago
Blocks: 1168428
(Assignee)

Updated

a year ago
Duplicate of this bug: 1301917
Marking as verified on Firefox 51 beta based on https://bugzilla.mozilla.org/show_bug.cgi?id=1301917#c9.
status-firefox51: fixed → verified
Flags: qe-verify+
You need to log in before you can comment on or make changes to this bug.