379729 - browser will freeze when reloading live bookmarks

Status: VERIFIED FIXED

(Firefox :: Bookmarks & History, defect)

Description

[(not reading, please use [e-mail] instead)]

browser occasionally freezes, relates to places?

yesterday in #places, littlemutt commented that he gets a cpu spike and freeze.  I think I have seen it too, and just saw it again.  

note, I think littlemutt was running with a build with neil's fix for bug #337868, which is similar to the fix in bug #337855.

this time, I was running with a patch from bug #337855, so when it happened I heard a lot of disk and saw this on the console (from bug #337855):

*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks
XXX save off containerOpen: true
XXX reset containerOpen: true
*** _rebuild(): _resultNode.title: Bookmarks

Comment 1

[(not reading, please use [e-mail] instead)]

[03 14:10:21] <Littlemutt> I've been seeing 'not responding' in the builds.  Launch with about 15 tabs, after the tabs have loaded - immediately open Bookmarks Organizer, - takes about two seconds on my machine, then a few seconds later the CPU goes to 100%, with bouts of 'not responding'.. I suspect its related to 'livemarks' , but I only have like 5 of those... is this a known problem waiting for fix? 
[03 14:10:34] <Littlemutt> I'm also on Vista HP, so it could be a Vista issue
[03 14:11:26] <sspitzerMsgMe> Littlemutt:  I may be seeing that too, are you seeing anything in the console?
[03 14:11:52] <Littlemutt> no
[03 14:12:23]  * dietrich tries to reproduce on xp
[03 14:12:40] <Littlemutt> It only happens on the initial start up of Firefox, subsequent openings of the Organizer are fine
[03 14:12:51] <sspitzerMsgMe> I think I was seeing:  ASSERT: null node
[03 14:12:55] <sspitzerMsgMe> in the console when this happened
[03 14:13:02] <sspitzerMsgMe> I'll keep an eye out
[03 14:13:20] <sspitzerMsgMe> wee, just got the assert!
[03 14:13:39] <sspitzerMsgMe> under
[03 14:13:44] <sspitzerMsgMe> MV_V_invalidateContainer()
[03 14:14:34] <sspitzerMsgMe> zoinks, never mind, that is from a patch in my own tree
[03 14:14:41] <sspitzerMsgMe> but, perhaps the recent checkin for neil
[03 14:14:42] <sspitzerMsgMe> for the toolbar
[03 14:14:44] <sspitzerMsgMe> has the same problem:
[03 14:14:51] <sspitzerMsgMe>         invalidateContainer: function MV_V_invalidateContainer(aNode) {
[03 14:14:51] <sspitzerMsgMe>           var parentElement = this._self.getElementForNode(aNode.parent);
[03 14:14:51] <sspitzerMsgMe>           if (!parentElement) {
[03 14:14:51] <sspitzerMsgMe>             // XXX probably a more targeted way of doing this
[03 14:14:51] <sspitzerMsgMe>             this._self._rebuild();
[03 14:14:51] <sspitzerMsgMe>             return;
[03 14:14:53] <sspitzerMsgMe>           }
[03 14:14:55] <sspitzerMsgMe>           parentElement._rebuild();
[03 14:14:57] <sspitzerMsgMe>         },
[03 14:14:59] <sspitzerMsgMe> in my case, aNode.parent is null
[03 14:15:16] <dietrich> sspitzerMsgMe: .parent is null for the root node
[03 14:17:57] <sspitzerMsgMe> dietrich: in that case, I should be calling this._self._rebuild(), as if there was no parentElement.
[03 14:17:59] <sspitzerMsgMe> let me fix my code
[03 14:18:11] <sspitzerMsgMe> about neil's code, I don't think he has this problem, at least according to LXR.
[03 14:18:37] -!- Mano [[e-mail]] has joined #places
[03 14:18:46] <Mano> back now
[03 14:18:52] <Mano> log please, dietrich / sspitzerMsgMe ?
[03 14:19:54]  * dietrich msgd
[03 14:20:27] <Mano> dietrich: thanks
[03 14:28:31] <dietrich> Littlemutt: not seeing the cpu spike on XP
[03 14:28:41] <dietrich> added lots of livemarks, restarted, opened organizer
[03 14:29:17] <Littlemutt> mmm OK, it could be a Vista issue - it acts strange at times when opening Outlook - or my system is just not powefull enough maybe - 
[03 14:30:16] <Littlemutt> I can quickly ctrl+tab thru a bunch of tabs and get 'not responding' as well... so its probably me
[03 14:31:17] <Littlemutt> carry on, I'll be quiet now 

Comment 2

[(not reading, please use [e-mail] instead)]

just saw this again.  anyone else (besides me and littlemutt) seeing this?

Comment 3

[(not reading, please use [e-mail] instead)]

related to loading live bookmarks.  i can make it happen by forcing a reload of a live bookmark in the personal toolbar, for example.

Comment 4

[Neil Deakin]

No issue here. Where are those debugging messages coming from, something you added yourself?

Comment 5

[(not reading, please use [e-mail] instead)]

> Where are those debugging messages coming from, something you added yourself?

yes, those debug messages were coming from changes locally.

try this:

1)  create a new profile
2)  right click on the "Latest Headlines" livebookmark on the personal toolbar and "Reload Live Bookmark".

for me, that will temporarily freeze the browser.

Comment 6

[(not reading, please use [e-mail] instead)]

update, I had the bm organizer open and in addition to being slow, chomping a lot of disk, I also got a lot of these asserts:

###!!! ASSERTION: Invalid index for item adding: greater than count: 'Not Reache
d', file c:/builds/trunk-no-places/mozilla/toolkit/components/places/src/nsNavHi
storyResult.cpp, line 3046

Comment 7

[Peter van der Woude [:Peter6]]

bug 329534 most probably depends on this one.

Comment 8

[Radek 'sysKin' Czyz]

If I go to Windows Task Manager and activate "I/O writes" and "I/O write bytes" then I can check that reloading a simple (six-entry) live bookmark makes firefox write count rise by about 330 and byte count by about 400 KB.

That's a large number of very very small, uncached writes.

Also, locking bookmarks.html (so that it's not kept in sync) doesn't help at all.

Hopefully that helps a bit...

Comment 9

[Dietrich Ayala (:dietrich)]

i'm not able to reproduce this on mac.

however, the livemark service does a rapid series of inserts of bookmarks and annotations when a livemark loads. this should be wrapped up in a transaction (using bmsvc.begin/endUpdateBatch).

Comment 10

[Robert Sayre]

(In reply to comment #9)
> i'm not able to reproduce this on mac.
> 

I wrote the livemark service on a mac, iirc, so this makes sense.

> however, the livemark service does a rapid series of inserts of bookmarks and
> annotations when a livemark loads. this should be wrapped up in a transaction
> (using bmsvc.begin/endUpdateBatch).

Do I just need to wrap them, or is the NS_NOT_REACHED assertion an indication of deeper problems?

Comment 11

[(not reading, please use [e-mail] instead)]

from my steps to reproduce in commment #5, they involve a new profile.

I just set these environment variables:

NSPR_LOG_MODULES=mozStorage:5
NSPR_LOG_FILE=C:\home\mozilla-nspr.log

and tried again.  I'm seeing a flurry (5,000 total?) of the following sql statements:

5720[5bfd378]: INSERT OR REPLACE INTO goog_white_domain_new VALUES (?1, ?2)
5720[5bfd378]: Resetting statement: 'INSERT OR REPLACE INTO goog_white_domain_ne
w VALUES (?1, ?2)'

and 

5720[5bfd378]: INSERT OR REPLACE INTO goog_black_url_new VALUES (?1, ?2)
5720[5bfd378]: Resetting statement: 'INSERT OR REPLACE INTO goog_black_url_new V
ALUES (?1, ?2)'

perhaps I was confusing the livemark freeze with what was actually a url classifier freeze?

Comment 12

[(not reading, please use [e-mail] instead)]

that said, even when I run the new profile a second time, and add a new livemark (for planet.mozilla.org), there is lots of disk io (and SQL statements) even when there isn't a lot of activity to the url classifier.

Comment 13

[Tony Chang (Google)]

I think that's normal.  With a new profile, url classifier will download the the phishing URL list from the server a few minutes after start up.  We reuse the same mozStorageStatement for each URL which explains the flurry of debug statements.  I'd be surprised if this blocks the UI since all the url classifier sql work is done on a separate thread, although it may cause a bit of slowdown.

mozStorage doesn't have any global locks does it?  Would doing a long transaction on a background thread block other queries?

Comment 14

[(not reading, please use [e-mail] instead)]

tony:  thanks for the info about the url classifier.  I'll spin off what I was seeing to another bug, but I don't think it's related to this issue, as you poing out.

Comment 15

[(not reading, please use [e-mail] instead)]

thanks dietrich for comment #9!

batching does help (patch and some performance numbers coming).

but also, at least for the scenario of reloading
http://planet.mozilla.org/rss20.xml as a livemark on the toolbar (after opening
it), there are gains to be made with toolbar.xml.

as the livemark gets updated, we get a lot of "itemChanged" notifications and
there are some things we can do in toolbar.xml to avoid finding, removing,
creating, and then inserting the parent element back into the toolbar (and then
calling updateChevron(), which is a recent change I made).

Comment 16

[(not reading, please use [e-mail] instead)]

numbers for the upcoming patch:

without batch:

"latest headlines" consistently took about 400ms in handleResult(), followed by lots of disk io
http://planet.mozilla.org/rss20.xml took 1200 ms in handleResult(), ,followed by lots of disk io

with batch:

"latest headlines" consistently took about 200ms in handleResult(), without lots of disk io
http://planet.mozilla.org/rss20.xml took 300 ms in handleResult(), again, without lots of disk io

this is with new profiles each time, on my Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9a5pre) Gecko/20070524 Minefield/3.0a5pre build (debug build, which is not ideal for perf testing, but still.)

Comment 17

[(not reading, please use [e-mail] instead)]

Attachment: patch

Comment 18

[Robert Sayre]

Comment on attachment 266104 [details] [diff] [review]
patch

>Index: nsLivemarkService.js
>     } 
>     finally {
>       this._processor.listener = null;
>       this._processor = null;
>       this._livemark.locked = false;
>     }
>+    
>+    this._bms.endUpdateBatch();

If an exception occurs here, endUpdateBatch will never be called. My read of the bookmarks service indicates that beginUpdateBatch and endUpdateBatch need to be matched. Comments in the idl warn that this is the case, and reading the source, the consequences seem pretty dire.

Comment 19

[(not reading, please use [e-mail] instead)]

Attachment: updated patch

robert is 100% corret, mismatched begin / end batch would be very bad.

the finally block is the right place, thanks robert.

Comment 20

[Robert Sayre]

Comment on attachment 266119 [details] [diff] [review]
updated patch

this is the right place, but please move it to the beginning of the block. Otherwise errors accessing the properties of _processor or _listener could prevent it from executing.

Comment 21

[(not reading, please use [e-mail] instead)]

Attachment: patch (as checked in)

Comment 22

[(not reading, please use [e-mail] instead)]

fix checked in.

Checking in nsLivemarkService.js;
/cvsroot/mozilla/toolkit/components/places/src/nsLivemarkService.js,v  <--  nsLi
vemarkService.js
new revision: 1.14; previous revision: 1.13
done

as for the performance problem with toolbar.xml, I believe that to be the root cause of the original issue I reported here, so I'll keep this bug open for that work.

Comment 23

[Dietrich Ayala (:dietrich)]

(In reply to comment #22)
> 
> as for the performance problem with toolbar.xml, I believe that to be the root
> cause of the original issue I reported here, so I'll keep this bug open for
> that work.
> 

which toolbar problem? can you provide more detail here?

there's a mention of invalidateContainer in comment #1. however, that seems to be fixed from mano's recent rewrite:

http://lxr.mozilla.org/mozilla/source/browser/components/places/content/toolbar.xml#619

Comment 24

[(not reading, please use [e-mail] instead)]

> which toolbar problem? can you provide more detail here?

Sorry for the delay in answering your questions, Dietrich.

Looking at my patches in bug #337855 with:

LOG("_rebuild(): _resultNode.title: " + this._resultNode.title);

We were calling _rebuild() [which is not cheap] for the menu.  Interesting, the title from my comment #1, we have:

*** _rebuild(): _resultNode.title: Bookmarks

So that looks like we were rebuilding the top level "Bookmarks" menu on reloading live bookmarks.

Asaf has improved things, but I haven't re-checked to see if we rebuild that menu on reloading of livebookmarks.

Thoughts and comments:  

you may have to open the bookmarks menu one to see this problem, and then reload live bookmarks.  And the live bookmark may have to be at the top level.  finally, if the bookmark is on the personal toolbar folder, we need to make sure we don't rebuild the toolbar (and the menu for the livebookmark) more than we need to.

Comment 25

[Dietrich Ayala (:dietrich)]

(In reply to comment #24)
> We were calling _rebuild() [which is not cheap] for the menu.  Interesting, the
> title from my comment #1, we have:
> 
> *** _rebuild(): _resultNode.title: Bookmarks
> 
> So that looks like we were rebuilding the top level "Bookmarks" menu on
> reloading live bookmarks.
> 
> Asaf has improved things, but I haven't re-checked to see if we rebuild that
> menu on reloading of livebookmarks.
> 

i confirmed that we're not calling _rebuild() at any level when a livemark reloads, only at the time of initial display. live update occurs thereafter, items being inserted individually.

> Thoughts and comments:  
> 
> you may have to open the bookmarks menu one to see this problem, and then
> reload live bookmarks.  And the live bookmark may have to be at the top level. 
> finally, if the bookmark is on the personal toolbar folder, we need to make
> sure we don't rebuild the toolbar (and the menu for the livebookmark) more than
> we need to.
> 

i verified all of these scenarios. live update occurs properly in each.

Comment 26

[Tracy Walker [:tracy]]

verified with Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9a7pre) Gecko/2007072505 Minefield/3.0a7pre

in litmus: http://litmus.mozilla.org/show_test.cgi?id=3968 sort of, it's the reload rss feed test case

Comment 27

[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