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

RESOLVED WORKSFORME

Status

()

defect
--
critical
RESOLVED WORKSFORME
10 years ago
9 years ago

People

(Reporter: whimboo, Unassigned)

Tracking

(4 keywords)

3.5 Branch
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)

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

10 years ago
Would seem related to bug 490035
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
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
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.
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
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
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.
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
Posted patch improvement (obsolete) — Splinter Review
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.
Attachment #378676 - Attachment is obsolete: true
Posted patch patch v0.4 (obsolete) — Splinter Review
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
Posted patch patch v0.5 (obsolete) — Splinter Review
v0.4 plus:
- onItemChanged check if we are changing "title" property before trying to update a tag
Attachment #378693 - Attachment is obsolete: true
Posted patch patch v0.6 (obsolete) — Splinter Review
v0.5 plus:
- fixes another excludeItems case on onItemRemoved
- removes a useless getItemType on onItemChanged
Attachment #378717 - Attachment is obsolete: true
Posted patch patch v.07 (obsolete) — Splinter Review
- fix other excludeItems cases
Posted patch patch v0.7 (obsolete) — Splinter Review
wrong attachment before
Attachment #378728 - Attachment is obsolete: true
Attachment #378736 - Attachment is obsolete: true
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
(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
Posted patch patch v0.8 (obsolete) — Splinter Review
- 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.
Posted patch patch v0.9 (obsolete) — Splinter Review
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.
Posted patch patch v1.0 (obsolete) — Splinter Review
- 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
Depends on: 494370
Depends on: 494371
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/
Depends on: 324430
Depends on: 494382
OS: Mac OS X → All
Hardware: x86 → All
(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.
Depends on: 494383
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.
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.
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.
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?
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.
Flags: wanted1.9.1.x+

Comment 47

10 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
(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: 9 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.