493731 - Restoring bookmarks from a JSON file can lock up the browser for a while

Status: RESOLVED WORKSFORME

(Firefox :: Bookmarks & History, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.5; en-US; rv:1.9.1b5pre) Gecko/20090519 Shiretoko/3.5b5pre ID:20090519035556

Using the Restore from JSON backup feature leaves my browser in a locked state for about 2 minutes while I wasn't able to do anything. The beach ball was visible all the time and after a while I got the following unresponsive script warning:

A script on this page may be busy, or it may have stopped responding. You can stop the script now, or you can continue to see if the script will complete.

Script: file:///Applications/Shiretoko.app/Contents/MacOS/components/nsPlacesDBFlush.js:192

The file from which I have restored my bookmarks is about 450kB in size. It's not so big so I wonder how many ppl will see this when they want to restore their bookmarks. Asking for blocking1.9.1 to get this bug on the radar for now.

Comment 1

[Marco Bonardo [:mak]]

i just checked and restore from JSON is using a batch, so i'm not sure why we end up locking in placesDBFlush::onItemChanged

Comment 2

[Shawn Wilsher :sdwilsh]

Somebody please tell me we are doing this batched.  Also, what happens in Firefox 3.0 here?

Comment 3

[Jesper Hansen]

Would seem related to bug 490035

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I did the same restore procedure with Firefox 3.0.8 and it has been finished within around 3s. So we have a regression here against Firefox 3.0.

The unresponsive script warning is not always the same. Now I got the following message:

Script: file:///Applications/Shiretoko.app/Contents/MacOS/modules/utils.js:771

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This regressed between beta2 and beta 3. Will go on to get a finer window.

Comment 6

[Mike Beltzner [:beltzner, not reading bugmail]]

Henrik: do you see the slow script warning dialog as referenced in comment 3? Blocking & assigning to Dietrich (though he may re-assign at will!)

Comment 7

[Marco Bonardo [:mak]]

I can probably follow Henrik with this.

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Regressed between the builds 08121202 and 08121302 and the following changeset ids:

http://hg.mozilla.org/releases/mozilla-1.9.1/rev/62a0552da6fa
http://hg.mozilla.org/releases/mozilla-1.9.1/rev/58e38927aaca

Checkins: http://hg.mozilla.org/releases/mozilla-1.9.1/pushloghtml?fromchange=62a0552da6fa&tochange=58e38927aaca

If someone of you can see it, please tell. Otherwise I would run a hg bisect.

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+2]]

While testing this with a debug around the above regression window I get the following assertion a couple of times:

###!!! ASSERTION: Invalid index for item adding: greater than count: 'Not Reached', file /data/build/shiretoko/toolkit/components/places/src/nsNavHistoryResult.cpp, line 3387

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Ok, so the patch on bug 468836 is causing this hang for me. Without it the unresponsive script warning doesn't appear and the restore is finished in a couple of seconds.

There is one more thing I have to mention. The hang only happens when I run it on existing bookmarks and tags. There are a couple of those entries in my database so we probably fail in removing those entries. Restoring against the initial database works fine. Here some stats about my places.sqlite:

{"places_file_id":"XXX",
 "places_file_size":716800,
 "moz_anno_attributes_cnt":9,
 "moz_annos_cnt":281,
 "moz_bookmarks_cnt":1820,
 "moz_bookmarks_roots_cnt":5,
 "moz_favicons_cnt":1,
 "moz_historyvisits_cnt":6,
 "moz_historyvisits_temp_cnt":0,
 "moz_inputhistory_cnt":0,
 "moz_items_annos_cnt":212,
 "moz_keywords_cnt":41,
 "moz_places_cnt":905,
 "moz_places_temp_cnt":0,
 "bookmark_cnt":1451,
 "folder_cnt":366,
 "separator_cnt":3,
 "dynamic_container_cnt":0,
 "bookmark_nontag_cnt":903,
 "livemark_container_cnt":0,
 "livemark_child_cnt":0,
 "visits_per_place_avg":3,
 "visits_per_place_max":5,
 "visits_per_place_min":1,
 "places_visited_unique_cnt":2,
 "visit_date_oldest":"Tue 19 May 2009 17:56:20 GMT",
 "visit_date_newest":"Tue 19 May 2009 18:36:03 GMT",
 "visit_date_avg":"Tue 19 May 2009 18:11:54 GMT",
 "tag_cnt":140,
 "tag_size_avg":3.914285714285714,
 "favicon_data_size_avg":580,
 "favicon_nonnull_data_size_avg":580,
 "favicon_nonnull_cnt":1,
 "session_unique_cnt":6,
 "frecency_first_bucket_visit_cnt":6,
 "frecency_second_bucket_visit_cnt":6,
 "frecency_third_bucket_visit_cnt":6,
 "frecency_fourth_bucket_visit_cnt":6,
 "frecency_first_bucket_place_unique_cnt":2,
 "frecency_second_bucket_place_unique_cnt":2,
 "frecency_third_bucket_place_unique_cnt":2,
 "frecency_fourth_bucket_place_unique_cnt":2,
 "history_expire_days":180,
 "history_expire_days_min":90,
 "history_expire_sites":40000,
 "extensions":[]}

Further I see a couple of assertions:

###!!! ASSERTION: Removing item we don't have: 'Not Reached', file /data/build/shiretoko/toolkit/components/places/src/nsNavHistoryResult.cpp, line 3472

###!!! ASSERTION: Invalid index for item adding: greater than count: 'Not Reached', file /data/build/shiretoko/toolkit/components/places/src/nsNavHistoryResult.cpp, line 3387

Comment 11

[Dietrich Ayala (:dietrich)]

to clarify, he said that the steps are actually this:

- new profile
- import his bookmarks.json from a different profile
- import his bookmarks.json from a different profile again

the slow-script dialog shows 1-3 times, and the import finishes successfully (as far as he could tell).

Comment 12

[Marco Bonardo [:mak]]

i don't think that bug is the culprit... i think probably that happens due to the taggingservice cache... and exactly i'm starting thinking we could be doing wrong things everywhere we cache itemIds, after a restore.

Comment 13

[Dietrich Ayala (:dietrich)]

Attachment: shark profile

Comment 14

[Marco Bonardo [:mak]]

reassigning to Dietrich since i have a medical visit and i won't be available for some hour. I'll continue investigating on this as soon as i come back.

Comment 15

[Dietrich Ayala (:dietrich)]

Attachment: improvement

now that we remove tags (need to find bug #) when we remove bookmarks, there's no need to do it when restoring JSON. this brought restore time down to a minute with my large profile, from many minutes (eventually just killed the process).

Comment 16

[Marco Bonardo [:mak]]

you can directly filter out tags root in the above check that pushes roots into the childIds array and use if (this._utils.isRootItem(rootItemId)) instead of the else if check.

Comment 17

[Marco Bonardo [:mak]]

Attachment: above improvement with my comments + fix strict warnings skipping static nodes in menu.xml

Comment 18

[Marco Bonardo [:mak]]

Attachment: don't remove tags + don't look static nodes (strict warning) + skip adding items to excludeItems nodes (assertion)

Comment 19

[Marco Bonardo [:mak]]

Attachment: patch v0.4

don't remove tags
don't look static nodes (strict warning)
skip adding items to excludeItems nodes (assertion)
get itemType only once per itemAdded per result

Comment 20

[Marco Bonardo [:mak]]

Attachment: patch v0.5

v0.4 plus:
- onItemChanged check if we are changing "title" property before trying to update a tag

Comment 21

[Marco Bonardo [:mak]]

Attachment: patch v0.6

v0.5 plus:
- fixes another excludeItems case on onItemRemoved
- removes a useless getItemType on onItemChanged

Comment 22

[Marco Bonardo [:mak]]

Attachment: patch v.07

- fix other excludeItems cases

Comment 23

[Marco Bonardo [:mak]]

Attachment: patch v0.7

wrong attachment before

Comment 24

[Mike Beltzner [:beltzner, not reading bugmail]]

This is looking like the front-end long pole at the moment ... do we have an ETA?

Comment 25

[Shawn Wilsher :sdwilsh]

(In reply to comment #24)
> This is looking like the front-end long pole at the moment ... do we have an
> ETA?
Before mak left on irc:
feel free to use my patch as you prefer... but i doubt this will make the freeze... we can maybe fix this as a late QA issue... or for next RC or in a maintenance release...

So, I am pretty sure we won't have anything tonight for this.  We /may/ have something tomorrow.  The last attachment helps out a lot, but it doesn't get us back to anything close to Firefox 3.0 speeds, and we aren't sure why it's taking longer at this time.  We'll continue to hammer on this tomorrow.

Comment 26

[Dietrich Ayala (:dietrich)]

yeah we're still beachballing for a minute during a restore of a big backup.

bug 463513 looks to be the culprit, but it's not clear why. i'm looking into whether backing it out is an option, as well as continuing to look into fixes.

Comment 27

[Mike Beltzner [:beltzner, not reading bugmail]]

Unblocking; we'll take this in a RC ridealong if it's ready, otherwise 3.5.1.

Suggested relnote based on STR from comment 11:

Importing bookmarks and history from another profile may take several minutes, during which time the browser will be unresponsive or show a constant busy indicator.

Comment 28

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to comment #27)
> Importing bookmarks and history from another profile may take several minutes,
> during which time the browser will be unresponsive or show a constant busy
> indicator.

Mike, I would suggest to transform it a bit. Comment 11 is an example like how that behavior can easily be reproduced. We should probably more general. And we don't restore the history, right?

Restoring bookmarks and tags from a backup into an existing profile can take several minutes, during which time the browser will be unresponsive or show a constant busy indicator.

Comment 29

[Marco Bonardo [:mak]]

Attachment: patch v0.8

- fixed toolbar.xml popups updating (skip static nodes)
- skip tagginService onItemAdded if the tag has been created through createTag, this saves us a getItemType for each added tag.

ugh. i receive a bunch of onBeginUpdateBatch onEndUpdateBatch in nsPlacesDBFlush during the restore... while i should only get one at the start and one at the end... wtf?

Comment 30

[Marco Bonardo [:mak]]

(In reply to comment #29)
> ugh. i receive a bunch of onBeginUpdateBatch onEndUpdateBatch in
> nsPlacesDBFlush during the restore...

nevermind, my bad logging this time.

Comment 31

[Marco Bonardo [:mak]]

Attachment: patch v0.9

better query for mDBGetItemProperties

Comment 32

[Marco Bonardo [:mak]]

notice on insertBookmark we spend quite some time updating frecency for every new bookmark, and again for every new tag, but if i don't updateFrecency on tags i see some unit test failing. That sounds bogus.

Comment 33

[Dietrich Ayala (:dietrich)]

filed bug 494249 for an idea i was toying with last night. it puts the whole restore process in a generator, yields periodically during the restore.

Comment 34

[Dietrich Ayala (:dietrich)]

mak: can you split the patch on this bug up, filing separate bugs? there are so many changes to so many different parts of the code, i'm worried about regressions.

Comment 35

[Marco Bonardo [:mak]]

Attachment: patch v1.0

- go back to previous "single-result" approach in tagging service
- allow results to be explicitly sent out-of-scope (idl change)

This is mostly experimental, i'm sending to the tryserver.
Will then start splitting the patch into single bugs.

Comment 36

[Marco Bonardo [:mak]]

(In reply to comment #35)
> - go back to previous "single-result" approach in tagging service

and this is back leaking, the reason we did change that. Probably stopObserving could allow obtain the same result.

this build contains patch v1.0, i'd like to know if anything changes about time needed for the restore.
https://build.mozilla.org/tryserver-builds/[e-mail]-try-c5f43c580f4/

Comment 37

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to comment #36)
> this build contains patch v1.0, i'd like to know if anything changes about time
> needed for the restore.
> https://build.mozilla.org/tryserver-builds/[e-mail]-try-c5f43c580f4/

The perf improvements for this build are dramatic! Now running the same steps as reported takes only 3-4s for the whole process. No beach ball and slow script warning is visible anymore.

Comment 38

[Marco Bonardo [:mak]]

Comment on attachment 379106 [details] [diff] [review]
patch v1.0

i've filed a bunch of dependant bugs on various discoveries i've done while investigating this. Those generate a slightly different version than v1.0 due to the leaking problem (i reverted back the multiple results solution, but with .stopObserving() idl change, that we can eventually sneak into 1.9.1 with an additional interface), so i'll generate a new build to test if we can reach that way same result as with 1.0.
Thanks for testing that!

Comment 39

[Marco Bonardo [:mak]]

the new version made up of all dependant bugs is building on the tryserver, should be ready in about 1 hour, i won't be here by then, but will be available later.

Comment 40

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This build looks fine. Same results as reported before with the former try server build.

Comment 41

[Marco Bonardo [:mak]]

So, the most important change that caused this problem is Tagging service change from one open result to many results created on demand. This change was mostly due to the fact we were leaking a bunch of things leaving the result open till late xpcom-shutdown.

2 possible solutions:
- take the patch in bug 324430 (with special interface for 1.9.1): this will speed up all the cases where we leave results around, so not only restore, and will give back the major gain. Unfortunately there's actually no way to detect when a result is no more used and waiting to be cycle collected, so is up to the developer to mark result as "i'm done with it, you can stop updating it".
- we can try to revert the tagging service change to have a single result, that will bring back a quite big leak though in all xpcshell tests. We can try investigating the leak and see if something can be done about it.

other dependent patches are really small changes that will enhance restore perf even more, potentially making restore faster than 3.0.

Comment 42

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Marco, could this also speed-up times on shutdown? As we know there are a couple of open bug reports which handle really long shutdown times.

Comment 43

[Marco Bonardo [:mak]]

(In reply to comment #42)
> Marco, could this also speed-up times on shutdown? As we know there are a
> couple of open bug reports which handle really long shutdown times.

That's not its purpose, but i suppose in some situation it could do that, i'm thinking to cases where some result is still alive, you close the browser with some option that will hit bookmarks or history, and it will continue to update them even if they should be killed. I don't have numbers, not this is current scope of the above patches, so that would require a separate investigation. Reducing Tshutdown is a target for .next afaik.

Comment 44

[Marco Bonardo [:mak]]

Dietrich, we should take one of the two solutions in comment 41 for 3.5, since this regressed restore but i expect other perf regressions in any other heavy tagging task.

Comment 45

[Michał Gołębiowski-Owczarek [:mgol]]

How bug 468836 can be marked fixed if it depends on this one?

Comment 46

[Marco Bonardo [:mak]]

(In reply to comment #45)
> How bug 468836 can be marked fixed if it depends on this one?

yes, i don't see a relation, removed dependancy.

Comment 47

[Jed Leahy]

this is still an issue in 3.5.2, are there plans for it to be resolves in 3.6.x?
I just get the beach ball and stays that way for 15min+ until I kill the app..
mac mini core-duo 1.66Ghz + 2GB ram  cheers, jed  jedi.theone -at- gmail -dot- com

Comment 48

[Gervase Markham [:gerv]]

Bug 451915 - move Firefox/Places bugs to Firefox/Bookmarks and History. Remove all bugspam from this move by filtering for the string "places-to-b-and-h".

In Thunderbird 3.0b, you do that as follows:
Tools | Message Filters
Make sure the correct account is selected. Click "New"
Conditions: Body   contains   places-to-b-and-h
Change the action to "Delete Message".
Select "Manually Run" from the dropdown at the top.
Click OK.

Select the filter in the list, make sure "Inbox" is selected at the bottom, and click "Run Now". This should delete all the bugspam. You can then delete the filter.

Gerv

Comment 49

[Dietrich Ayala (:dietrich)]

Is this still reproducible?

Comment 50

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to comment #49)
> Is this still reproducible?

No, it works fine in most recent Minefield builds like Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:2.0b8pre) Gecko/20101212 Firefox/4.0b8pre. That means one or more of the dependencies have fixed it.