User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:59.0) Gecko/20100101 Firefox/59.0 Build ID: 20171218220523 Steps to reproduce: I have 2 computers with about 35000 bookmarks on each. Most are the same, but there are some additional folders at the end of bookmarks on each one of the 2 computers, that are not on the other. 1. I Removed other sync add-ons, in order to ensure they don't interfere with Firefox Sync (xmarks 4.5.0.8, because it is totally broken since the move to Web Extensions) 2. Logged in to Sync on one computer and synchronized only bookmarks , logged in to Sync on a second computer , and selected "Sync Now" in the Tools menu, which should start an initial sync as I understand (initial versus an incremental sync) Actual results: Sync is horribly slow, never completed, it took at least 4 hours but never completed since every time I had to exit Firefox earlier, therefore I don't know if it never ends, or it might end after more than several hours if I wait enough. I know it didn't finish because I always see it "working" or cycling in the Firefox right drop down menu, and when I move the mouse over the cycling animation, the pop-up text is: "Last sync - January 1" , which means it didn't sync yet. Some bookmarks get synched/updated/added/reordered in the bookmarks menu, but as I wrote , there is no indication that the operation completed successfully. (It is complicated to see if all bookmarks got synched correctly, since bookmarks get reordered , but that is another issue) It happens both with the current Firefox Nightly 59.0a1 (2017-12-18) (64-bit), and the current release 57.0.2 During those hours Firefox becomes very janky,very slow to respond. The CPU usage of Firefox jumps to above 60% on a dual core computer. I have a fast SSD, 64-bit Windows 10 OS, and more than enough memory (12 GB, Firefox uses about 3 GB), so it is not disk accesses or lack of memory that is causing the slowness, but CPU operations (or bad algorithm) Expected results: Firefox Sync should be fast, in the order of seconds (or at least minutes), not hours, even with tens of thousands of bookmarks. CPU usage should not be that high for several hours. Note: I suspect this might be caused or related to Bug 1405242, or because Firefox Sync doesn't use bookmarks batch operations enough. It may also be a problem of Sync itself, not related to bookmarks batch operations.

Firstly, note that 35,000 bookmarks is a lot. The vast majority of our users have less than 2000. That doesn't mean we shouldn't support more, but most of our tests and timing analysis are based on that and priorities will be affected. Bug 1405242 might help a little, but it'll need Sync to use the new variants of the APIs. Though I believe Sync is currently doing other work that might help.

It's probably bug 1339390 - we know that many thousands of bookmarks in a folder takes (almost) forever to order. There's no easy fix for that, but while it's cold comfort, we do intend landing a change in 60 that side-steps this issue. The other (also poor) option is to arrange the bookmarks so there's a max of a few thousand bookmarks in each folder.

(In reply to Mark Hammond [:markh] from comment #2) > It's probably bug 1339390 - we know that many thousands of bookmarks in a > folder takes (almost) forever to order. There's no easy fix for that, but > while it's cold comfort, we do intend landing a change in 60 that side-steps > this issue. The other (also poor) option is to arrange the bookmarks so > there's a max of a few thousand bookmarks in each folder. I have many folders, but with up to around 1000 bookmarks in each one of them. In my opinion there might be another cause. the problem can be also due to updating the "Recently bookmarked" sub-menu. For each bookmark that is inserted/updated/deleted, a notification is usually sent to it, and it performs (for each bookmark!) a search/"select" on all bookmarks to sort and find the ones which were most recently updated, instead of doing it once at the end of all operations, or on demand, only when the "Recently bookmarked" menu is opened. It was the main cause for some slow bookmarks operations bugs I have seen in the past, when there are many bookmarks (and therefore the search to find the most recently updated bookmarks, takes longer over all bookmarks). If I remember correctly it became slow after the change to make Places asynchronous. If I remember correctly in the past I could check easily whether it was the problem by changing a configuration option in about:config (to not show and update the recently bookmarked sub-menu), but currently I can't find it in Nightly, and from a quick search on the internet it seems the option was removed.

(In reply to nivtwig from comment #3) > In my opinion there might be another cause. the problem can be also due to > updating the "Recently bookmarked" sub-menu. > For each bookmark that is inserted/updated/deleted, a notification is > usually sent to it, and it performs (for each bookmark!) a search/"select" > on all bookmarks to sort and find the ones which were most recently updated, > instead of doing it once at the end of all operations, or on demand, only > when the "Recently bookmarked" menu is opened. The old recently bookmarked section of the "Bookmarks" menu did that (now removed), I believe the new one accessible from the library button on the toolbar does not (I certainly can't find the code if it does). > It was the main cause for some slow bookmarks operations bugs I have seen in > the past, when there are many bookmarks (and therefore the search to find > the most recently updated bookmarks, takes longer over all bookmarks). If I > remember correctly it became slow after the change to make Places > asynchronous. There's various reasons bulk operations are slow at the moment and we're working on improving those for places (e.g. bug 1405242, bug 1340498). As Mark said, the Sync ones may help as well. > If I remember correctly in the past I could check easily whether it was the > problem by changing a configuration option in about:config (to not show and > update the recently bookmarked sub-menu), but currently I can't find it in > Nightly, and from a quick search on the internet it seems the option was > removed. As I mentioned earlier, this has been removed.

(In reply to Mark Banner (:standard8) (mainly afk until 3rd Jan) from comment #4) > (In reply to nivtwig from comment #3) > > In my opinion there might be another cause. the problem can be also due to > > updating the "Recently bookmarked" sub-menu. > > For each bookmark that is inserted/updated/deleted, a notification is > > usually sent to it, and it performs (for each bookmark!) a search/"select" > > on all bookmarks to sort and find the ones which were most recently updated, > > instead of doing it once at the end of all operations, or on demand, only > > when the "Recently bookmarked" menu is opened. > > The old recently bookmarked section of the "Bookmarks" menu did that (now > removed), I believe the new one accessible from the library button on the > toolbar does not (I certainly can't find the code if it does). > I still see a "Recently Bookmarked" section in the bookmarks menu both in Nightly, and Firefox release (57.0.2). Did you mean that the "Recently Bookmarked" section (or sub-menu) was removed, or just the code that caused the performance problems?

I'm not sure when the code Mark refers to was removed, but the UI which shows recent bookmarks appears to be at https://searchfox.org/mozilla-central/source/browser/base/content/browser-places.js#1849 and is only executed as the menu is being displayed. If you set the preference "services.sync.log.appender.console" to "Debug", and open the browser console (Ctrl+Shift+J), you should find Sync starts spewing lots of info to the console. If the most recent items after the apparent hang start with "Recording children of ..." then I'm confident the problem will be as I mentioned above - but if it is something else, then please copy the log to a file and attach it here, and we might be able to work out what is going on.

(In reply to nivtwig from comment #5) > I still see a "Recently Bookmarked" section in the bookmarks menu both in > Nightly, and Firefox release (57.0.2). > Did you mean that the "Recently Bookmarked" section (or sub-menu) was > removed, or just the code that caused the performance problems? Bug 1401238 removed "Recently Bookmarked" from the Bookmarks menu on the main menu bar, and the "Show your bookmarks" menu on the toolbar (see attachment 8909838 [details]). This was some code that affected performance, but generally only after the menu had been opened once iirc (and/or when doing things within the menu). If you click the "View History, saved bookmarks and more" toolbar button, or the Library section of the app menu, then under Bookmarks you get the new "Recently Bookmarked". This doesn't dynamically update (only when the menu is opened - which uses the query that markh referenced in comment 6).

(In reply to Mark Hammond [:markh] from comment #6) > spewing lots of info to the console. If the most recent items after the > apparent hang start with "Recording children of ..." Actually, that's not quite correct - but the logs would certainly help us determine if the reorder is the problem.

(In reply to Mark Hammond [:markh] from comment #6) > I'm not sure when the code Mark refers to was removed, but the UI which > shows recent bookmarks appears to be at > https://searchfox.org/mozilla-central/source/browser/base/content/browser- > places.js#1849 and is only executed as the menu is being displayed. > > If you set the preference "services.sync.log.appender.console" to "Debug", > and open the browser console (Ctrl+Shift+J), you should find Sync starts > spewing lots of info to the console. If the most recent items after the > apparent hang start with "Recording children of ..." then I'm confident the > problem will be as I mentioned above - but if it is something else, then > please copy the log to a file and attach it here, and we might be able to > work out what is going on. I tried a different scenario - an initial sync from a clean profile without bookmarks, in order to update it with my ~35000 bookmarks: On the same computer, I created a new clean profile using the -profilemanager command line option. (There was no "Recently bookmarked" section in the bookmarks menu of the clean profile) I Logged in to Sync, and sync started. I used the config option and browser console to see the sync debug log as you suggested. 50 minutes have already passed and it didn't finish (and it is already too much time), but the messages I see currently and all of this time, do not seem to be related to what you suspected, see below an example - These kind of messages are repeating endlessly: 1515107279696 Sync.Engine.Bookmarks.Store DEBUG Applying record UwAZk89AXq93 1515107279696 Sync.Engine.Bookmarks.Store DEBUG Remote parent is Q10nb2ITv585 1515107279700 Sync.Engine.Bookmarks.BookmarkSyncUtils DEBUG insertSyncBookmark: Item UwAZk89AXq93 is not an orphan 1515107279827 Sync.Engine.Bookmarks.Store DEBUG Applying record UwQTxJJ-4beS 1515107279827 Sync.Engine.Bookmarks.Store DEBUG Remote parent is C04-QheS9mVi 1515107279832 Sync.Engine.Bookmarks.BookmarkSyncUtils DEBUG insertSyncBookmark: Item UwQTxJJ-4beS is not an orphan 1515107279922 Sync.Engine.Bookmarks.Store DEBUG Applying record UwYq4BAXT4TH 1515107279922 Sync.Engine.Bookmarks.Store DEBUG Remote parent is bWF0C5X-Snot 1515107279928 Sync.Engine.Bookmarks.BookmarkSyncUtils DEBUG insertSyncBookmark: Item UwYq4BAXT4TH is not an orphan If I understand correclty it seems from the messages (If I understand them correctly) that the insertion of bookmarks items alone comsumes all of this time (until now, maybe later the bookmarks::reorder will take more time ...)

Thanks for the info. (In reply to nivtwig from comment #9) > seem to be related to what you suspected, see below an example - These kind > of messages are repeating endlessly: To be clear, these messages were continuously spewing out after 50 minutes, right until you closed Firefox? > If I understand correclty it seems from the messages (If I understand them > correctly) that the insertion of bookmarks items alone comsumes all of this > time (until now, maybe later the bookmarks::reorder will take more time ...) If the answer to the above is "yes", then that would appear to be the case :(

(In reply to Mark Hammond [:markh] from comment #10) > (In reply to nivtwig from comment #9) > > seem to be related to what you suspected, see below an example - These kind > > of messages are repeating endlessly: > > To be clear, these messages were continuously spewing out after 50 minutes, > right until you closed Firefox? > I didn't close Firefox. Yes, What I described was happening all the time since the Sync start and until around 50 minutes and probably later (I checked several times until around 50 minutes), and the Sync finished successfully after around 1 hour and 15 minutes (according to last sync time minus the time it started Sync) in this case, which is different than the case in the original bug report where the second computer to sync is not a clean profile without bookmarks (except the defaults), but also has many bookmarks with new bookmark additions to sync.

Should this be fixed with your patch, Kit?

(In reply to Julie McCracken (:julie) from comment #12) > Should this be fixed with your patch, Kit? *) If the patch is tracked in another bug, can you write the bug number? *) According to my findings (comment 9 and comment 11) it took about 1 hour for inserting just 35000 bookmarks. Can someone tell if it is supposed to be that long for purely inserting 35000 bookmark records to the places database? If not, the problem is not the pure insertions to the database but some other thing around it in the algorithm.

surely 1 hour is a long time, though you should also consider Sync does the work in background and *tries* to not interrupt you from using the browser in the meanwhile. On the other side only 0,5% of telemetry users reports having more than 10k bookmarks (and we should still subtract tags from these numbers), so the priority is relative to the benefit for most users. May I ask, out of curiosity, how did you generate a so large amount of bookmarks?

(In reply to Marco Bonardo [::mak] from comment #14) > surely 1 hour is a long time, though you should also consider Sync does the > work in background and *tries* to not interrupt you from using the browser > in the meanwhile. > On the other side only 0,5% of telemetry users reports having more than 10k > bookmarks (and we should still subtract tags from these numbers), so the > priority is relative to the benefit for most users. May I ask, out of > curiosity, how did you generate a so large amount of bookmarks? This is a simplification, but without delving into the details: Reading news sites every day, I click on links to news or articles to open them in new tabs in the background to read them later, and sometimes I open links from articles that point to other interesting readings. I have many areas of interest so lets say I open ~60 articles a day for reading later, but on average have the time to read only ~30 a day equals 30 net a day, multiply by about 300 days a year is 9000 a year, multiply by several years, and you get 35000 ... (I keep them to read later when I have time ..., and sometimes I go back an read many of them, the ones that interest me most from the list I kept) And some additional info: I thought maybe instead of syncing, I will try to import the bookmarks from file to a new profile, to see how much time does the insertion alone take (assuming reading from file is not the problem here), without the sync algorithm. 35000 bookmarks took about 5-10 minutes, and I found later there is a bug for it (Bug 1320534), and Google Chrome performs it in seconds..., so I guess the sync algorithm takes most of the time here (about an hour).

(In reply to Mark Banner (:standard8) from comment #1) > Firstly, note that 35,000 bookmarks is a lot. The vast majority of our users > have less than 2000. That doesn't mean we shouldn't support more, but most > of our tests and timing analysis are based on that and priorities will be > affected. > > Bug 1405242 might help a little, but it'll need Sync to use the new variants > of the APIs. Though I believe Sync is currently doing other work that might > help. If you have tests for that, then does anyone have info how much time does it take to do an initial sync for 2000 bookmarks? I suspect that it is also slow and takes minutes. If the code complexity behaves linearly then it should take about 2-3 minutes, which is also very slow for something that should take at most seconds (35000 bookmarks is about 18 times 2000, and 35000 takes at least 50 minutes, so 50/18= ~2-3 minutes)

(In reply to Mark Banner (:standard8) from comment #1) > Firstly, note that 35,000 bookmarks is a lot. The vast majority of our users > have less than 2000. That doesn't mean we shouldn't support more, but most > of our tests and timing analysis are based on that and priorities will be > affected. > > Bug 1405242 might help a little, but it'll need Sync to use the new variants > of the APIs. Though I believe Sync is currently doing other work that might > help. To confirm my assumption in comment 16, I tested an initial sync of 2140 bookmarks to another profile without bookmarks in the bookmarks menu (I disconnected from Sync in the second profile, deleted all bookmarks, and reconnected to Sync) The sync took 4-5 minutes for 2140 bookmarks, which is bad, for something that should take seconds. This slow sync needs to happen every time you disconnect and reconnect from Sync. Therefore, the "average" case is also very slow, and I think it should be given high priority. In cast it matters, the bookmarks I tested were organized in 5 folders on the top level, each folder with 350-450 bookmarks, and around 10 bookmarks on the top level.

Hi, thanks for the report. This is definitely not a good experience, and something we're working to improve. The way Sync works today is roughly "get the IDs of all bookmarks changed locally since the last sync, download encrypted blobs for new bookmarks from the server, decrypt each one, resolve conflicts and duplicates with locally changed bookmarks, insert them into the local database one-by-one, inflate records for outgoing bookmarks one-by-one, encrypt each one, and upload the encrypted blobs." We've cut down on some of the HTTP overhead with download and upload batching. We can't do much about the encryption overhead: 35k bookmarks on a first sync means we'll need to encrypt and upload 35k JSON blobs. Bug 1305563 should make other parts of this pipeline better. First, we'll stage all outgoing bookmarks into an in-memory database table, with a schema that's closer to how Sync represents the records. This cuts down on how many queries we run to fetch these: currently 2-7 *per bookmark*. Second, we read the complete tree structure, but not contents, into memory, and use that to merge and dedupe. This further cuts down on reads and writes, especially when the trees have conflicts, or change significantly on the server. Third, we update the entire local database in one big batch of SQL statements, instead of a transaction with reads and writes per bookmark. I jotted down some early numbers for large trees in bug 1305563, comment 65 and bug 1305563, comment 74. Now that the patch has settled down, I'll run and post some more benchmarks. Those numbers don't account for crypto or HTTP overhead, but still look positive. So, the TL;DR is that it takes a long time, especially on a first or large sync, to read, encrypt, and upload records, and decrypt and apply on receiving devices. But the way we do this today is inefficient, and we're optimistic that the new approach for syncing bookmarks in bug 1305563 will improve it.

(In reply to Kit Cambridge (they/them) [:kitcambridge] from comment #18) > We've cut down on some of the HTTP overhead with download and upload > batching. We can't do much about the encryption overhead: 35k bookmarks on a > first sync means we'll need to encrypt and upload 35k JSON blobs. *) To test roughly how much time encryption should take (the encryption overhead) I exported my current 40000 bookmarks to a plain .html file (size:37MB), and encrypted+zipped it using 7-zip, with the default normal compression, and AES-256 encryption with a password . It took only 4-5 seconds (!). And decrypting it back from .7z encrypted file to a .html file took less than a second. I understand that encrypting the bookmarks one by one might take more time than my results, but I don't think it should take so much more time in the order of tens of minutes in the case of 35000 bookmarks (or minutes in the case of 2000 bookmarks)... *) In the 35000 case I described above (not at the opening report, it was mainly decryption as I understand, not encryption, since the receiving end had almost no bookmarks. It mostly downloaded 35000 bookmarks from the server and then had to decrypt in order to insert to the local database, and even though it does it one by one I don't think it should take so much time. There were almost no uploaded bookmarks from the local database to the server (maybe about 10), and therefore no need for encryption. Therefore I think the encryption explanation for the time it takes does not explain it, and maybe someone should profile the sync process to see what is really going on (since your numbers for the time it takes for merging also don't explain the amount of time I see) > Bug 1305563 should make other parts of this pipeline better. ... > I jotted down some early numbers for large trees in bug 1305563, comment 65 > and bug 1305563, comment 74. Now that the patch has settled down, I'll run > and post some more benchmarks. Those numbers don't account for crypto or > HTTP overhead, but still look positive. > *) Can you give any estimate, when will it land on Firefox Nightly ?

Will revisit this after Kit's patch lands.