399566 - Bookmarks and History menus open slower than other menus every time

Status: RESOLVED WORKSFORME

(Firefox :: Bookmarks & History, defect, P2)

Description

[dolphinling]

2007-10-11-04 linux trunk nightly (and others, not sure when it regressed)

With my places.sqlite file, the bookmarks and history menus open slowly, taking noticeably longer than the rest of the menus.

This does not happen in a clean profile. However, if I export my bookmarks to a bookmarks.html, then remove all traces of bookmarks and history from a clean profile, then import the bookmarks.html into the clean profile, the clean profile demonstrates the same slowness.

I do not have a lot of bookmarks--105 to be exact. Nor are they complexly structured--they're at most 2 folders deep.

Bug 385036 is similar, but says it only happens the first time the menu is opened. This happens to me every time the menu is opened.

I'd rather not attach my bookmarks file to bugzilla for eternity, but I would be fine emailing it to an individual. Boris, in bug 385036 you offered to look into it if someone gave you a testcase, is that offer still open? Anyone else with a bugzilla track record would be okay, too. Alternatively, I could try to minimize it to see if it's a specific bookmark causing the problem, but I'm pretty busy so I might not have time for a while.

Comment 1

[Boris Zbarsky [:bzbarsky]]

I don't think I'll be able to look into this in the near term.  sayrer, do you want to dtrace this?

Comment 2

[Mike Connor [:mconnor]]

This is basically unconfirmed, I haven't seen reports of this from anyone else.  Clearing nom until we get secondary confirmation or something measuring this.

Comment 3

[Tracy Walker [:tracy]]

dolphinling, I can't reproduce this using your instructions on Win, Mac or Linux.  

You'll need to do a little leg work here;  Track down a regression range, if any.  Also, Edit a failing bookmarks.html to your privacy satisfaction, then attache it here.

Comment 4

[dolphinling]

Attachment: testcase (import this into a new profile)

So I found I can reproduce by making a new profile and dragging the default home page to the bookmarks page over and over. (note that ctrl-d doesn't work, apparently that checks if the page has already been bookmarked, whereas dragging doesn't check.)

Comment 5

[dolphinling]

That attachment alone only affects the bookmarks menu.

History seems to be affected merely by visiting lots of pages: in a clean profile, opening all pages of the BBC News live bookmark in tabs, then closing them, and then moving through the menus shows the history menu being slow (but not the bookmarks, if no bookmarks have been added to this profile)

Comment 6

[dolphinling]

I'm trying to profile this with jprof and I'm not getting useful results at all. Should I be using JP_REALTIME?

Comment 7

[Boris Zbarsky [:bzbarsky]]

What settings are you using right now?  What do you mean by "useful results"?

Comment 8

[dolphinling]

Sorry, should have said those.

Right now I'm using JPROF_FLAGS="JP_DEFER JP_PERIOD=0.002".

"Not getting useful results" means that over several trials with both a clean profile and the one with the bookmarks testcase imported, the profiles show just about the same number of calls, even though the one with the bookmarks is very noticeably slower to appear on the screen.

Comment 9

[Boris Zbarsky [:bzbarsky]]

I assume that you're starting/stopping your profile in the right places, right?  That is, starting before any of the code involved runs, and stopping after the menu has appeared?

To get decent resolution for profiles on the order of a second or less you really need to use JPROF_RTC_HZ=8192 (and make sure your kernel supports that and that the /proc stuff is set up right).

Comment 10

[dolphinling]

Yeah, I started the profile just before clicking on the menu and I stopped it after closing the menu. 

I'm adding RTC support to my kernel, I'll try profiling with that. The Jprof readme says I can get stuff from other programs mixed in with my results if I'm running with JP_RTC_HZ, is there any way around that? Or should I just close all my other running programs and try to do stuff as fast as possible?

Comment 11

[Boris Zbarsky [:bzbarsky]]

> The Jprof readme says I can get stuff from other programs mixed in with my
> results

Not quite.  It says that if there are times when Mozilla blocks on another program (usally the X server is the only issue here) it'll look like time is spent in the function we blocked in.  You'll see it right away; the profile will show time spent in _end or some such.  Just ignore it.

And yes, closing down other programs while profiling is a good idea.

Comment 12

[Dietrich Ayala (:dietrich)]

Was this resolved or at least mitigated by bug 399729?

Comment 13

[Marco Bonardo [:mak]]

history menu should be fast enough with the new super optimized query, but will get faster after fixing Bug 392399, and should not be a problem anymore (i've tested it with 200.000 visits without any slowdown.

Bookmark menu still lag with many bookmarks, i have tested with about 1000 bookmarks, it takes a while on first open, about a second, then it's faster on next opens, but still lagging a bit.

Comment 14

[Mike Schroepfer]

Ondrej you want to take this?

Comment 15

[Dietrich Ayala (:dietrich)]

He already has taken it :)

Would be great if the reporter or someone else using Linux could comment here if the problem is still very bad. There's been no dupes filed, and no new info since about 5 months ago, and per comment #12 there have been fixes in this area.

(In reply to comment #13)
> Bookmark menu still lag with many bookmarks, i have tested with about 1000
> bookmarks, it takes a while on first open, about a second, then it's faster on
> next opens, but still lagging a bit.
> 

Sure. We should mitigate that as much as possible. However, the reporter indicated that there was first-load penalty on every opening of the menu, which is more of a concern.

Comment 16

[dolphinling]

Sorry I haven't commented here in a while.

So the problem is not fixed. The bookmarks and history menus still open slower every time on my computer. Also, I suspect related, the URL bar dropwdown takes a full two seconds to populate when I type anything in it. However, I haven't seen anyone else report either of these issues, so I've suspected for a while that it could be specific to my computer.

I really don't know what would be causing it. I didn't get anything useful when profiling (though I don't think I ever got a profile with RTC). For a while I thought I might have messed up my hard drive performance, but my little cpu monitor widget definitely shows it being CPU-bound, hot hard drive. It could be that sqlite performance is very bad on my box, but I wouldn't know how to test that, or why it would be the case.

Does anyone have ideas for what I should test?

Comment 17

[Ondrej Brablc]

This is not a Linux specific problem, I can see a delay on first use on Windows too. There are simply too many SQL queries when opening bookmarks menu folder.

When a bookmark menu is opened it reads all the children, this is done with one query, however, right after this a menu item is created for each node in PlacesUtils.createMenuItemForNode. This function checks what type of node do we have by twice asking the annotation service (is it a livemark, is it a tag container). This does two database queries per bookmark folder displayed - a performance killer.

I would suggest that result nodes get livemark and tagContainer information for all their children when they load them. Instead of asking annotation service, nodes would be asking their parents for this information, if parent does not have this information, it would request it from annotation service.

Related bugs 416988, 417042, 398300.

Comment 18

[dolphinling]

Ondrej: This is not about the first time the menu is used. This is about *every* time the menu is used. This is also an issue for very small sets of bookmarks (the bookmarks.html attachment is more than enough to reproduce this on my computer) but other people have far more bookmarks and don't see this problem.

While general places-related performance bugs will probably help, there is a separate issue here that appears to affect only me (or nearly only me)

Comment 19

[Ondrej Brablc]

(In reply to comment #18)
> Ondrej: This is not about the first time the menu is used. This is about
> *every* time the menu is used. 

Sorry, I am working on too many similar bugs. I will take a look whether we can somehow debug why menu caching does not work for you.

Comment 20

[Ondrej Brablc]

Attachment: Test case - check whether menu stays built

(In reply to comment #18)
dolphinling: Please download the attached file to your local disk and open it in your freshly restarted Firefox (You may need to confirm security warning). Now check the values for both bookmarks and history (click on respective Check buttons). You should see both values as false. Now visit Bookmarks menu and click on Bookmarks check, you should see now value "true". With history you would get always false (I'm not convinced yet whether this is an error, but I would like to concentrate on bookmarks at the moment).

May be we could try to speed up this debugging session using some IM.

Comment 21

[Ondrej Brablc]

Attachment: Test case - check whether menu stays built (more details)

Sorry for bug spamming, I'm adding a version which gives more details.

Comment 22

[Asaf Romano (gone)]

Attachment: tentative patch

Comment 23

[Asaf Romano (gone)]

And honestly, I'd hope your patch on the other bug doesn't introduce node-fields like is-livemark, is-tag-container, etc.

Comment 24

[dolphinling]

(In reply to comment #20/comment #21)

In current trunk nightly, the attachment in comment 21 gives
Bookmarks: built=false
History  : built=false
...before opening the menus, and 
Bookmarks: built=true opened=true children=39
History  : built=false opened=false


(In reply to comment #22)
> Created an attachment (id=305609) [details]
> tentative patch

I applied this to current CVS (as of a few hours ago) and built, and unfortunately it doesn't help at all. :(


I'll try profiling again, but I'll need to rebuild for that.

Comment 25

[dolphinling]

So I'm having issues profiling. I've posted about them in m.d.performance, but I'm not hopeful they'll be solvable. Anyone have other suggestions for what to look at?

Comment 26

[Ondrej Brablc]

(In reply to comment #22)
> Created an attachment (id=305609) [details]
> tentative patch
> ...
> And honestly, I'd hope your patch on the other bug doesn't introduce
> node-fields like is-livemark, is-tag-container, etc.

This is a good patch, but probably for different bug, I would like to use it to fix bug 417729 (and it should help to solve bug 405765 and 417042 too).

(In reply to comment #25)
> So I'm having issues profiling. I've posted about them in m.d.performance, but
> I'm not hopeful they'll be solvable. Anyone have other suggestions for what to
> look at?

Do you have debug build? Can you export NSPR_LOG_MODULES=mozStorage:5 to your environment, start debug build and then check in the console what SQL statements get executed when you click on the Bookmarks menu for the second time?

Comment 27

[Dietrich Ayala (:dietrich)]

(In reply to comment #22)
> Created an attachment (id=305609) [details]
> tentative patch
> 

need review? or new patch coming?

Comment 28

[Ed]

I can confirm this on a Mac powerbook running 10.5.2 and FF 3.0B4. I am running on my old profile and have about 200 bookmarks which are nested 2, sometimes 3 deep.

Pressing Bookmarks takes maybe 5 seconds for the menu to appear, sometimes (but not always) it seems this delay happens each time I press bookmarks.

Comment 29

[Ed]

The delay also occurs if I open a new tab between accesses to bookmarks

Comment 30

[dolphinling]

Ed: can I ask a few questions to make sure we really are seeing the same issue?

1) Do all the menus except the history and bookmarks menus open instantaneously?
2) If you create a new profile, does the problem go away?
3) If you then import the bookmarks from the first testcase from this bug into that new profile, does the problem reappear?
4) Is the Awesomebar also very slow?

Ondrej: finally have time to work on the debug build, should get to it today.

Comment 31

[dolphinling]

Attachment: Console spew from *first* click of bookmarks menu

So I think I did this correctly...

The attachment shows the stuff spewed to the console the first time I click the bookmarks menu in a fresh start of the debug firefox with NSPR_LOG_MODULES=mozStorage:5

On the second and any subsequent clicks, there is no console spew whatsoever.

Comment 32

[Ondrej Brablc]

(In reply to comment #31)
> Created an attachment (id=309002) [details]
> Console spew from *first* click of bookmarks menu
> 
> So I think I did this correctly...
> 
> The attachment shows the stuff spewed to the console the first time I click the
> bookmarks menu in a fresh start of the debug firefox with
> NSPR_LOG_MODULES=mozStorage:5
> 
> On the second and any subsequent clicks, there is no console spew whatsoever. 
> 

So it does not generate any SQL queries but is slow on second click. This would mean that sqlite and places are not directly involved in this problem. I'm afraid I'm not the right one to help with this.

Comment 33

[Mike Connor [:mconnor]]

This really seems isolated, not sure why at all, but there's no dupes, no secondary confirmation, so not going to block on this, after discussion with dietrich and beltzner.

Comment 34

[kuro68k]

I can confirm that the history and bookmarks menus are slow in FF 3.0.1.

A simple fix for the history menu would be to simply cache the last ten URLs and closed tabs, instead of doing an SQL query as appears to be the case at the moment.

Comment 35

[dolphinling]

This went away when I recently upgraded my x server (from 1.3.0 to 1.5.2) and my xf86-video-intel driver (from 2.1.1 to 2.5.0), along with a pile of libraries and helper apps and the like. I'm even running with the NoAccel option to the driver to disable hardware acceleration (to fix corruption) and it's still now fast enough that bookmarks and history are just as fast as the other menus, and the URL bar dropdown takes < 1 second to appear, instead of > 2. 

Since no one else ever saw this, I'm going to close it as worksforme. However, on the offchance anyone wants to investigate what was happening to see if we were doing something wrong, I'll still be available for testing.

Comment 36

[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