1332225 - [meta] Investigate Firefox hanging while importing bookmarks/history/passwords from Google Chrome

Status: NEW

(Firefox :: Migration, defect)

Comment 1

[Justin Dolske [:Dolske]]

I'll assume Gijs meant to put a little more descriptive comment 0 here, such as:

There was discussion in bug 1331800 about the initial autoimport of Chrome data taking more than a minute, and making the browser non-responsive during that time. This is obviously pretty undesirable, as having a new Firefox user experience a minute-long hang during their very first interaction with the product is pretty terrible. At least with the old import wizard could see what was happening, but with automigration there's no indication of what's going on.

My conjecture in bug 1331800 comment 12 was that the hang might be due to swamping the event loop with thousands of Promises. Although now that I look at the code a little more carefully, I see we're actually batching up all the history entries into a single insertVisitsWrapper call, and not doing that for each entry. So, someone needs to do a little profiling here to see what's actually happening.

Comment 2

[Justin Dolske [:Dolske]]

Dao: can you help look into this?

I vaguely remember Gijs doing something in bug 1285041 to cause Chrome to generate lots of history (to make sure that fix was working), maybe that's useful here?

Comment 3

[Dão Gottwald [:dao]]

Gijs, do you have anything to add to comment 1? I know next to nothing about our import infrastructure.

Comment 4

[:Gijs (out for now; he/him)]

(In reply to Justin Dolske [:Dolske] from comment #1)
> I'll assume Gijs meant to put a little more descriptive comment 0 here, such
> as:

Egh, yeah, sorry. :-(

> My conjecture in bug 1331800 comment 12 was that the hang might be due to
> swamping the event loop with thousands of Promises. Although now that I look
> at the code a little more carefully, I see we're actually batching up all
> the history entries into a single insertVisitsWrapper call, and not doing
> that for each entry. So, someone needs to do a little profiling here to see
> what's actually happening.

Right, so, there's 3 things that automigrate imports: bookmarks, history and passwords.

Bookmarks get imported one by one, in part because there isn't a batch import API, that I know of.

History gets imported in one big chunk. That chunk could be very big. Marco has suggested at various times that it might make sense to have some kind of cutoff, e.g. only import history that is from the last 3 months or whatever. I don't know how long Chrome keeps history and/or if that would make a difference.

Passwords also get imported one by one, mostly because we have to de-dupe them carefully with existing login data, though with added work we could probably make that batched, too - I just doubt it's the bottleneck here.


I think the main problem is that we're not sure what's slow here. It could be a number of things:

- reading a lot of stuff from Chrome's bookmarks database (potentially while Chrome is open, which means we're read-only accessing their sqlite DB while ignoring the fact they have a lock on the DB...) is slow.
- the same, for history and/or passwords
- I don't think bookmark insertions are currently wrapped in a "hi, we're doing a batched insert" call to places. That might make a difference if importing while the Firefox UI is up, because for instance the bookmarks toolbar and other views might be visible and might be watching for changes. Batching things should avoid the callbacks that come with UI updates, I think? I wouldn't expect this to make a difference for history (because it's 1 call anyway) or passwords (because there's no direct UI).
- there's no bookmark tree insertion API, so we insert bookmarks 1 by 1. It's possible optimizing this might yield some results. When Marco and I discussed the impact of removing bookmarks 1 by 1 for the 'undo' functionality (bug 1285577), the impact was 1 or 2 orders of magnitude - but the timings were such (ie you needed to add/remove 1000s of items in an xpcshell test to get to user-noticeable lengths of time, and not a lot of people have that many bookmarks) that it wasn't clear that it was worth the overhead of adding a dedicated removal API. Perhaps we should re-check that when run in a UI environment to see if the UI being open makes a difference because of the observers etc., and do a similar check for insertion.
- it's possible that the fact that we have callbacks for the places insertions e.g. here ( https://dxr.mozilla.org/mozilla-central/source/browser/components/migration/ChromeProfileMigrator.js#338-356 ) makes the insertion of a lot of history slow. We could just yield but not have callbacks for each inserted row. I don't know if sqlite is any more efficient in that case. I also don't know if the places history insertion stuff uses 1 insert for each visit or is cleverer than that. That's also something that we could look into.


So yeah, there's a lot of options. Step 1 is figuring out how slow different parts are. To generate a bunch of history, what I did was navigating to any old website in chrome, and using the chrome developer tools to run a script with a setInterval that sets location.href to "#<different number", which all become different history entries in Chrome. Depending on the interval, this ramps up pretty quickly.

I don't have a lot of ideas for generating a bunch of bookmarks / passwords, but one thing you could also try is to just ask Chrome to import history from Firefox if you have a Firefox profile with a reasonable amount of these things.

Does that help?

Comment 5

[Dão Gottwald [:dao]]

Any idea how widespread the problem is? Can it be reproduced with "average" profiles or rather with pathological ones? Can I have the profile you generated? I'd like to avoid poking in the dark as much as possible.

Once we have a profile for reproducing this, seems like the next logical step would be to modify our code to skip importing history / passwords / bookmarks, respectively, and see if the problem persists.

Comment 6

[:Gijs (out for now; he/him)]

Attachment: History file from Chrome

(In reply to Dão Gottwald [:dao] from comment #5)
> Any idea how widespread the problem is?

No.

> Can it be reproduced with "average"
> profiles or rather with pathological ones?

Unsure, depends how you define those things.

> Can I have the profile you
> generated? I'd like to avoid poking in the dark as much as possible.

Do you mean a profile in terms of timing information? If so, I don't have a profile - I timed some numbers with Date.now() and a while loop in an xpcshell test to get them at the time, and I don't have those numbers anymore. In any case, they were only for the removal of items, so it wouldn't really give a complete picture anyway.

Or do you mean the Chrome profile I used? In which case, I've attached the History file. I'm not sure how representative it is of JW's experience. It might be best to ask him.

Comment 7

[Dão Gottwald [:dao]]

I meant the Chrome user profile. Justin, what kind of profile did you reproduce this with?

Comment 8

[Marco Bonardo [:mak]]

(In reply to :Gijs from comment #4)
> - I don't think bookmark insertions are currently wrapped in a "hi, we're
> doing a batched insert" call to places. That might make a difference if
> importing while the Firefox UI is up, because for instance the bookmarks
> toolbar and other views might be visible and might be watching for changes.
> Batching things should avoid the callbacks that come with UI updates, I
> think?

Batching doesn't do anything else than firing a "batch-start/end" notification, then it's a result that decides what to do about it (and the view depends on the result decisions).
The bookmarks toolbar is disabled by default though, so it should not matter for automigration?
There are other listeners, like the Star button, Sync, web-ext, that maybe matter, but it needs to be measured, and they don't care about an eventual batch.

> - there's no bookmark tree insertion API, so we insert bookmarks 1 by 1.
> It's possible optimizing this might yield some results.

Shouldn't make an extreme difference, since we use WAL. That said, we could have an insertTree API, just that I'm not sure how much we'd gain from it.

> - it's possible that the fact that we have callbacks for the places
> insertions e.g. here (
> https://dxr.mozilla.org/mozilla-central/source/browser/components/migration/
> ChromeProfileMigrator.js#338-356 ) makes the insertion of a lot of history
> slow. We could just yield but not have callbacks for each inserted row. I
> don't know if sqlite is any more efficient in that case.

We invoke the callback regardless. I don't expect to make a diff.

I also don't know
> if the places history insertion stuff uses 1 insert for each visit or is
> cleverer than that. That's also something that we could look into.

it's one by one, in a transaction. There's some overhead that could be saved.
But again, we should know if the slowdown is due to history, and if so, if it's due to the insertions or the notifications. Also, every visit addition causes a frecency recalculation, that is not the cheapest thing, there's an old comment there:
http://searchfox.org/mozilla-central/rev/30fcf167af036aeddf322de44a2fadd370acfd2f/toolkit/components/places/History.cpp#1054
And this is another point where visits additions can be improved.

Comment 9

[Marco Bonardo [:mak]]

to be very clear, the history system atm is not optimized for batch insertions of thousands of visits, and that's why I always suggested to limit the amount of entries we import. There is space for improvement, but no low hanging fruits.

Comment 10

[Justin [:JW_SoftvisionQA]]

The profile that I used is my personal Gmail profile that I have used every day at work since July 2015. BUT, This issue does not occur any more. Now everything automigrates over without a significant hang. It started working as expected after Gijs fix for 1331888.

See video below:

https://jwilliams-softvision.tinytake.com/sf/MTI4MjExOV80Nzk0NTkw

Comment 11

[Dão Gottwald [:dao]]

Gijs, are you actually seeing a problem with the user profile you made? If not, I'm inclined to resolve this as WFM, although perhaps we should use this bug to implement a history cap as Marco suggested, because that sounds like a sensible precautionary measure.

Comment 12

[:Gijs (out for now; he/him)]

(In reply to Justin [:JW_SoftvisionQA] from comment #10)
> The profile that I used is my personal Gmail profile that I have used every
> day at work since July 2015. BUT, This issue does not occur any more. Now
> everything automigrates over without a significant hang. It started working
> as expected after Gijs fix for 1331888.
> 
> See video below:
> 
> https://jwilliams-softvision.tinytake.com/sf/MTI4MjExOV80Nzk0NTkw

My changes in that bug only affect the 'undo' functionality, and shouldn't change anything for the import process itself.

That video still looks like the import itself causes lagginess in the browser - is that a video artifact?

Otherwise, is it possible that in cases where import doesn't hang the browser as much, maybe you're testing without having Chrome open in the background? It's possible that that makes a significant difference.


(In reply to Dão Gottwald [:dao] from comment #11)
> Gijs, are you actually seeing a problem with the user profile you made? If
> not, I'm inclined to resolve this as WFM, although perhaps we should use
> this bug to implement a history cap as Marco suggested, because that sounds
> like a sensible precautionary measure.

I've never tried (I always used manual import when testing the fix for bug 1285041, which was not directly about auto-import). I think the terribleness of the experience here warrants more investigation, so I don't think we should resolve as WFM until there's more clarity on what's going on.

Perhaps we can get an instrumented build to JW for testing?

Comment 13

[Justin [:JW_SoftvisionQA]]

(In reply to :Gijs from comment #12)
> 
> My changes in that bug only affect the 'undo' functionality, and shouldn't
> change anything for the import process itself.
> 
> That video still looks like the import itself causes lagginess in the
> browser - is that a video artifact?

The import does cause about 2-3 seconds of lag. It is a bit more acceptable than 1-2 minutes. I don't think there would be very many complaints about that. I also did have google chrome open (sorry I should have put my taskbar in the video).

> 
> Perhaps we can get an instrumented build to JW for testing?

I'd be happy to test this again.

Comment 14

[Justin Dolske [:Dolske]]

(In reply to :Gijs from comment #6)

> (In reply to Dão Gottwald [:dao] from comment #5)
> > Any idea how widespread the problem is?
> 
> No.

Well, yes. Maybe.

We have telemetry data on how long the import is taking - see the FX_MIGRATION_*_IMPORT_MS probes. On Beta 51, I see:

* 25% of Chrome users see a bookmark import > 5 seconds, 11% over 15 seconds
* 13% of Chrome users see a history import > 5 seconds, 14% over 15 seconds
* 1% of Chrome users see a logins import > 5 seconds, < 0.2% over 15 seconds

And for other browsers, for comparison:

* 23% of IE users see a bookmark import > 5 seconds, < 4% over 15 seconds
* 11% of Edge users see a bookmark import > 5 seconds, < 0.5% over 15 seconds
* < 0.3% of IE users see a history import > 5 seconds
* < 0.2% of Edge users see a history import > 5 seconds
* < 0.2% of IE users see a login import > 5 seconds
* < 0.2% of Edge users see a login import > 5 seconds

[The Edge data for Bookmarks is weirdly trimodal -- there's a peak around 0, a peak around 200ms, and a huge isolated bar in the 10 second bucket (with no distribution around it).]

That tells me:

1) It takes a long time to import bookmarks/history from Chrome for a lot of people.
2) IE and Edge bookmark/history imports are in much better shape than Chrome.
3) Logins are not a problem anywhere


Now, what we don't know for sure is to what degree these import times correlate with the browser being non-responsive. I think our (reasonable?) assumption was that this stuff is all async, and so a user's Firefox should be nice and responsive, even if it takes a while for the import to complete in the background. Bug 1331800 (and especially the video linked in comment 0 there) indicate that the browser may actually be non-responsive during that time. Which is Really Not Good.

My main concern is the non-responsiveness. Firefox being non-responsive for a minute on first-run is not acceptable. The actual import time is of secondary concern. If it takes a minute for your data to show up, but during that time Firefox is fast and responsive, well, ok I guess. (But let's make sure there we're not missing any reasonable optimizations.)


I'd suggest a few possible avenues of attack:

1) Have QA reproduce the original problem. It's strange that it seems to be working now... Can it be reproduced with the original build that demonstrated the problem? If not, what else might have changed? Same machine? Same background activity / test environment?

2) Generate a synthetic Chrome profile with lots of bookmarks and history, and profile it. Hopefully we can at least reproduce a modest slowness (import time), so we can confirm the hang (or not), and diagnose the cause.

3) Code inspection. Least favorite or reliable, but fresh eyes on code that had been slowly evolving (or rotting, if you're a pessimist ;) might reveal some problem areas or clues. (Of course, the main risks are that we find nothing, or try to optimize something without knowing if it has an effect.)

4) Enable automigration on all pre-release channels, and ask our community to help test. (Variation: ask MoCo developers to help test.)


For #2, in particular, I'd suspect that disk I/O performance may exacerbate the problem and make it easier to catch... Running things in a VM and/or using a profile on a slow USB thumbdrive are useful tricks.

Other suggestions welcome!

Comment 15

[Justin Dolske [:Dolske]]

(In reply to Marco Bonardo [::mak] from comment #8)

> The bookmarks toolbar is disabled by default though, so it should not matter
> for automigration?

Well, that's interesting... In the video from bug 1331800 -- https://jwilliams-softvision.tinytake.com/sf/MTI3MzY4M180Nzc2OTEy -- Justin enables the bookmark toolbar a few seconds after the main window comes up (at which point it immediately becomes non-responsive -- the toolbar button is still shown as depressed, and the toolbar itself doesn't actually get shown until for more than a minute.

Possible this is the cause, and not just an effect, of the hang?

Justin, are you including this step when trying to reproduce?

Comment 16

[Justin Dolske [:Dolske]]

(In reply to Marco Bonardo [::mak] from comment #9)
> to be very clear, the history system atm is not optimized for batch
> insertions of thousands of visits, and that's why I always suggested to
> limit the amount of entries we import.

This could also be something to consider (although I'm jumping past the "determine what's actually wrong" step). Importing only the last X days or Y top sites would seem smarter than just "import everything".

Although the telemetry indicates bookmarks are just as much a problem as history, and we do need to keep all your bookmarks.

Comment 17

[Justin Dolske [:Dolske]]

(In reply to Justin Dolske [:Dolske] from comment #14)

> We have telemetry data on how long the import is taking - see the
> FX_MIGRATION_*_IMPORT_MS probes.[...]
> And for other browsers, for comparison:

I forgot to add that we also have the FX_MIGRATION_*_QUANTITY probes...

For history, it's obvious that IE and Edge users are importing much less data. 95% of IE users have < 50 visits, and 95% of Edge users have < 10. For Chrome, you don't hit the 95% point until > 4000 visits. [We can only import "typed urls" from Edge, so that's naturally going to be lower. Interesting that even IE is so low even though we can import full history... I guess lots of people only use it to download another browser? :)]
 
For bookmarks, 95% of IE users have < 30, 95% of Edge users have < 5, while for Chrome the 95% point jumps to 115. These numbers are rather surprising -- for all browsers -- because that seems like so very very few bookmarks, and yet we're seeing 25% of Chrome users and 23% of IE users take > 5 seconds to import their bookmarks!

Comment 18

[Justin [:JW_SoftvisionQA]]

(In reply to Justin Dolske [:Dolske] from comment #15)
> 
> Well, that's interesting... In the video from bug 1331800 --
> https://jwilliams-softvision.tinytake.com/sf/MTI3MzY4M180Nzc2OTEy -- Justin
> enables the bookmark toolbar a few seconds after the main window comes up
> (at which point it immediately becomes non-responsive -- the toolbar button
> is still shown as depressed, and the toolbar itself doesn't actually get
> shown until for more than a minute.
> 
> Possible this is the cause, and not just an effect, of the hang?
> 
> Justin, are you including this step when trying to reproduce?

Dolske: Loading the bookmark toolbar does not have an effect on making the browser non-responsive. See video below:
https://jwilliams-softvision.tinytake.com/sf/MTI5MTg5OV80ODE2Mzkz

Comment 19

[Justin Dolske [:Dolske]]

(In reply to Justin [:JW_SoftvisionQA] from comment #18)

> Dolske: Loading the bookmark toolbar does not have an effect on making the
> browser non-responsive. See video below:
> https://jwilliams-softvision.tinytake.com/sf/MTI5MTg5OV80ODE2Mzkz

I'm a little confused -- this video doesn't show you opening the bookmark toolbar. The original video has you right-clicking on the navbar and selecting "Bookmarks Toolbar" to enable it, within a couple seconds of the window first coming up.

Comment 20

[Justin [:JW_SoftvisionQA]]

Yes. I thought you were saying earlier that you suspect the Bookmarks Toolbar being the culprit so I showed the same hang without the Bookmark Toolbar. Maybe I am understanding you incorrectly?

Comment 21

[Justin Dolske [:Dolske]]

I'm trying to understand if you were able to reproduce the minute-plus long hang, and if you had attempted to do so with the bookmark toolbar open.

Comment 22

[Justin [:JW_SoftvisionQA]]

No, I am not able to reproduce the minute-plus long hang. Gijs and I looked at this yesterday (with builds before and after his fix) but could not reproduce. We could not find a reason for this as my Google Chrome profile has not changed.

Comment 23

[Dão Gottwald [:dao]]

Filed bug 1338522 on adding telemetry for this.

Comment 24

[Dão Gottwald [:dao]]

(In reply to Justin Dolske [:Dolske] from comment #14)
> 3) Code inspection. Least favorite or reliable, but fresh eyes on code that
> had been slowly evolving (or rotting, if you're a pessimist ;) might reveal
> some problem areas or clues. (Of course, the main risks are that we find
> nothing, or try to optimize something without knowing if it has an effect.)

Filed bug 1338800 on one potential issue.

Comment 25

[:Gijs (out for now; he/him)]

Marco, how much stuff is going to break if we stop dispatching 'visit' and/or 'titlechanged' notifications for these URIs? It looks like batching those up actually causes more slowness / hanging than notifying for them individually. :-\

How many observers know about / care about onBeginUpdateBatch / onEndUpdateBatch and is sending those going to make anything better?

Comment 26

[Dão Gottwald [:dao]]

(In reply to :Gijs from comment #25)
> It looks like batching
> those up actually causes more slowness / hanging than notifying for them
> individually. :-\

In a way this makes sense, as the spread-out notifications might allow the UI to briefly come back to life every now and then, so this might indeed be better from a user's perspective. However, depending on how exactly the main thread handles this, there's some gray area where I think you might fall victim to measurement limitations. If you're using my patch from bug 1338522, you might want to try a shorter timer interval. With the 1s default it might be under-reporting on short hangs and be biased towards longer ones.

That being said, if you see a big impact on the main thread with the pooled notifications, that's still very much a problem even if it somehow turns out to be better than the spread-out notifications. If I understood your approach correctly, we end up doing the same amount of work on the main thread, so I'd be surprised if this was a complete solution.

Comment 27

[Marco Bonardo [:mak]]

(In reply to :Gijs from comment #25)
> Marco, how much stuff is going to break if we stop dispatching 'visit'
> and/or 'titlechanged' notifications for these URIs?

not notifying visits is likely to break history in general, not notifying titlechanged is feasible if we add title to onVisit (bug 1280601) and update consumers to also update their title at onVisit. This for updatePlaces clearly, the docshell path should still notify title changes, but that's fine.

> It looks like batching
> those up actually causes more slowness / hanging than notifying for them
> individually. :-\

Yes, I agree with Dao here, if you notify everything in a single runnable, the mainthread will hang for a long time, vs a lot of small hangs in the single notification case. I can't tell which one is better, none likely. And I don't have a short term solution.
What I'd like to happen in the future, is that we abandon the single notifications, and move to batch notifications, so that a consumer can just register for specific places notifications and get them in batch when there's a large change. Something like
PlacesUtils.addListener("history-visit-added") and get an array of the changes at once when multiple visits are inserted. The current system is really inefficient, first of all because each consumer must listen to everything, even things it doesn't care about, second because there's no concept of "all these changes are happening at once".
It's not a short term thing, but it may be feasible incrementally, adding the notifications and then converting consumers.

> How many observers know about / care about onBeginUpdateBatch /
> onEndUpdateBatch and is sending those going to make anything better?

Only UI views are likely to make use of those, I don't expect the addition of those to do anything useful for your case.

Comment 28

[Marco Bonardo [:mak]]

FYI, I filed bug 1340498 to investigate Places observers redesign. But it's clearly not something ready today to solve your problem :(

Comment 29

[:Gijs (out for now; he/him)]

(In reply to Marco Bonardo [::mak] from comment #27)
> (In reply to :Gijs from comment #25)
> > Marco, how much stuff is going to break if we stop dispatching 'visit'
> > and/or 'titlechanged' notifications for these URIs?
> 
> not notifying visits is likely to break history in general, not notifying
> titlechanged is feasible if we add title to onVisit (bug 1280601) and update
> consumers to also update their title at onVisit. This for updatePlaces
> clearly, the docshell path should still notify title changes, but that's
> fine.
> 
> > It looks like batching
> > those up actually causes more slowness / hanging than notifying for them
> > individually. :-\
> 
> Yes, I agree with Dao here, if you notify everything in a single runnable,

I mean, I batch them up per 100 or 1000 at a time, but even so, still seeing hanginess.

> the mainthread will hang for a long time, vs a lot of small hangs in the
> single notification case. I can't tell which one is better, none likely. And
> I don't have a short term solution.
> What I'd like to happen in the future, is that we abandon the single
> notifications, and move to batch notifications, so that a consumer can just
> register for specific places notifications and get them in batch when
> there's a large change. Something like
> PlacesUtils.addListener("history-visit-added") and get an array of the
> changes at once when multiple visits are inserted. The current system is
> really inefficient, first of all because each consumer must listen to
> everything, even things it doesn't care about, second because there's no
> concept of "all these changes are happening at once".
> It's not a short term thing, but it may be feasible incrementally, adding
> the notifications and then converting consumers.

Right, this doesn't help in the short term. I think I'll park this patch and look specifically at what omitting the titlechanged things (by incorporating them into onVisit) would get us.

> > How many observers know about / care about onBeginUpdateBatch /
> > onEndUpdateBatch and is sending those going to make anything better?
> 
> Only UI views are likely to make use of those, I don't expect the addition
> of those to do anything useful for your case.

:-(

Comment 30

[:Gijs (out for now; he/him)]

Preliminary update: initial data from my WIP patch suggests bug 1344282 will make importing bookmarks roughly 9-10 times faster, and cause about half as much mainthread jank as measured by the code from bug 1338522, though YMMV depending on how bookmarks are structured, how many duplicate URLs there are, whether those URLs exist in the places DB already at the time of import, how much padding is in the JSON file, whether sync is already on, ... etc. I'll probably put up patches on Monday and then iterate further to see if there's anything else we can do.

Comment 31

[Justin Dolske [:Dolske]]

(In reply to Justin Dolske [:Dolske] from comment #14)

> We have telemetry data on how long the import is taking - see the
> FX_MIGRATION_*_IMPORT_MS probes. On Beta 51, I see:
> 
> * 25% of Chrome users see a bookmark import > 5 seconds, 11% over 15 seconds
> * 13% of Chrome users see a history import > 5 seconds, 14% over 15 seconds
> * 1% of Chrome users see a logins import > 5 seconds, < 0.2% over 15 seconds

That "14%" in the middle line (for history) appears to have been a typo. Should be "4%".

Comment 32

[:Gijs (out for now; he/him)]

Not actively working on this at this point.

Comment 33

[Marco Bonardo [:mak]]

Bug 1346979 and bug 1338800 are likely the last low hanging fruits we could take.
Anything else is more complex architectural work.

Comment 34

[Leo Reiss]

I'm trying to import my history from Chrome but it's freezing completely and even after minutes it doesn't come back and I have to end the process. The history file from Chrome has 18Mb. Last version of Firefox.

Comment 35

[Leo Reiss]

Attachment: Big history file from Chrome (zipped)

Big history file to make some tests.