The default bug view has changed. See this FAQ.

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

RESOLVED WORKSFORME

Status

()

Firefox
Bookmarks & History
--
critical
RESOLVED WORKSFORME
8 years ago
6 years ago

People

(Reporter: whimboo, Unassigned)

Tracking

(4 keywords)

3.5 Branch
hang, perf, regression, relnote
Points:
---
Dependency tree / graph
Bug Flags:
blocking-firefox3.5 -
wanted-firefox3.5 +

Firefox Tracking Flags

(status1.9.1 wanted)

Details

(Whiteboard: [splitted to dependent bugs][status is comment 41][TSnap])

Attachments

(1 attachment, 11 obsolete attachments)

(Reporter)

Description

8 years ago
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.
Flags: blocking-firefox3.5?
i just checked and restore from JSON is using a batch, so i'm not sure why we end up locking in placesDBFlush::onItemChanged
Somebody please tell me we are doing this batched.  Also, what happens in Firefox 3.0 here?

Comment 3

8 years ago
Would seem related to bug 490035
(Reporter)

Comment 4

8 years ago
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
Keywords: regression, regressionwindow-wanted
(Reporter)

Comment 5

8 years ago
This regressed between beta2 and beta 3. Will go on to get a finer window.
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!)
Assignee: nobody → dietrich
Flags: blocking-firefox3.5? → blocking-firefox3.5+
I can probably follow Henrik with this.
Assignee: dietrich → mak77
(Reporter)

Comment 8

8 years ago
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.
Keywords: regressionwindow-wanted
(Reporter)

Comment 9

8 years ago
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
(Reporter)

Comment 10

8 years ago
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
(Reporter)

Updated

8 years ago
Blocks: 468836
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).
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.
Created attachment 378498 [details]
shark profile
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.
Assignee: mak77 → dietrich
Created attachment 378665 [details] [diff] [review]
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).
Attachment #378665 - Flags: review?(mak77)
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.
Created attachment 378676 [details] [diff] [review]
above improvement with my comments + fix strict warnings skipping static nodes in menu.xml
Attachment #378665 - Attachment is obsolete: true
Attachment #378665 - Flags: review?(mak77)
Created attachment 378680 [details] [diff] [review]
don't remove tags + don't look static nodes (strict warning) + skip adding items to excludeItems nodes (assertion)

Updated

8 years ago
Attachment #378676 - Attachment is obsolete: true
Created attachment 378693 [details] [diff] [review]
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
Attachment #378680 - Attachment is obsolete: true
Created attachment 378717 [details] [diff] [review]
patch v0.5

v0.4 plus:
- onItemChanged check if we are changing "title" property before trying to update a tag
Attachment #378693 - Attachment is obsolete: true
Created attachment 378728 [details] [diff] [review]
patch v0.6

v0.5 plus:
- fixes another excludeItems case on onItemRemoved
- removes a useless getItemType on onItemChanged
Attachment #378717 - Attachment is obsolete: true
Created attachment 378736 [details] [diff] [review]
patch v.07

- fix other excludeItems cases
Created attachment 378737 [details] [diff] [review]
patch v0.7

wrong attachment before
Attachment #378728 - Attachment is obsolete: true
Attachment #378736 - Attachment is obsolete: true

Updated

8 years ago
Attachment #378737 - Attachment is patch: true
Attachment #378737 - Attachment mime type: application/octet-stream → text/plain
This is looking like the front-end long pole at the moment ... do we have an ETA?
Whiteboard: [ETA?]
(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.
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.
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.
Flags: wanted1.9.1.x+
Flags: wanted-firefox3.5+
Flags: blocking-firefox3.5-
Flags: blocking-firefox3.5+
Keywords: relnote
(Reporter)

Comment 28

8 years ago
(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.
Summary: Restoring bookmarks from a JSON file locks up UI completely → Restoring bookmarks from a JSON file can lock up the browser for a while
Created attachment 378850 [details] [diff] [review]
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?
Attachment #378737 - Attachment is obsolete: true
(In reply to comment #29)
> ugh. i receive a bunch of onBeginUpdateBatch onEndUpdateBatch in
> nsPlacesDBFlush during the restore...

nevermind, my bad logging this time.
Created attachment 378875 [details] [diff] [review]
patch v0.9

better query for mDBGetItemProperties
Attachment #378850 - Attachment is obsolete: true
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.
Depends on: 494249
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.
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.
Created attachment 379106 [details] [diff] [review]
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.
Attachment #378875 - Attachment is obsolete: true

Updated

8 years ago
Depends on: 494370

Updated

8 years ago
Depends on: 494371

Updated

8 years ago
Depends on: 494372
(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/mak77@bonardo.net-try-c5f43c580f4/

Updated

8 years ago
Depends on: 324430

Updated

8 years ago
Depends on: 494382
(Reporter)

Updated

8 years ago
OS: Mac OS X → All
Hardware: x86 → All
(Reporter)

Comment 37

8 years ago
(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/mak77@bonardo.net-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.

Updated

8 years ago
Depends on: 494383

Updated

8 years ago
Attachment #379106 - Attachment is obsolete: true
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!
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.
(Reporter)

Comment 40

8 years ago
This build looks fine. Same results as reported before with the former try server build.
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.
(Reporter)

Comment 42

8 years ago
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.
(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.
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.

Updated

8 years ago
Whiteboard: [ETA?] → [splitted to dependent bugs][status is comment 41]
Whiteboard: [splitted to dependent bugs][status is comment 41] → [splitted to dependent bugs][status is comment 41][TSnap]
How bug 468836 can be marked fixed if it depends on this one?

Updated

8 years ago
No longer blocks: 468836
(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.
status1.9.1: --- → wanted
Flags: wanted1.9.1.x+

Comment 47

8 years ago
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
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
Component: Places → Bookmarks & History
QA Contact: places → bookmarks
Is this still reproducible?
Assignee: dietrich → nobody
(Reporter)

Comment 50

6 years ago
(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.
Status: NEW → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.