497732 - Slow performance and large places.sqllite

Status: RESOLVED INCOMPLETE

(Firefox :: Bookmarks & History, defect)

Description

[Duncan Loveday]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-GB; rv:1.9.0.10) Gecko/2009042316 Firefox/3.0.10
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-GB; rv:1.9.0.10) Gecko/2009042316 Firefox/3.0.10

Over a period of weeks or months I've noticed Firefox getting progressively slower. Today I traced the problem to the presence of a 144M "places.sqllite" in my default profile. Removing/renaming this immediately restored performance to normal levels as did creating a new clean profile.

I have a zip of the profile but it's rather large - 16M (unpacks to about 150M). Not sure if you'd want me to attach it here.

With this profile what I noted was slow performance opening file:// URLs under a specific path file:///C:/starteam/Construction/software/BPTM/BPTMPresentation/code/source/com/bt/util/logging/presentation/*. I could dramatically improve performance by changing any part of that path, e.g. move the files to file:///C:/starteam/Construction/software/BPTM/BPTMPresentation/code/source/com/bt/util/logging/presentationXXX/ or file:///C:/starteam/Construction/software/BPTM/BPTMPresentation/code/source/comXXX/bt/util/logging/presentation/. So my guess is that there are a lot of duplicate database keys records matching that first path or something like that that's resulting in heavy database activity.

The slowing has the nature of occasional pauses of a couple of seconds.

Reproducible: Always




If there's sufficient interest in this I can try to prepare a test case and/or attach the zipped profile here.

Comment 1

[Duncan Loveday]

I meant to add: Performance could also be restored to normal by unchecking "keep my history for at least nnn days" although keeping it checked and reducing the number of days to 1 did not improve it.

Here's the profile

$ pwd
/cygdrive/c/documents and settings/803042764/Application Data/Mozilla/Firefox/Profiles/jeiww0v7.default
$ ls -l
total 148327
-rwx------+ 1 803042764 ????????         2067 Jun 11 17:56 blocklist.xml
drwx------+ 2 803042764 ????????            0 Jun 11 23:28 bookmarkbackups
-rwx------+ 1 803042764 ????????        13040 Dec 10  2008 bookmarks.bak
-rwx------+ 1 803042764 ????????        13040 Dec 10  2008 bookmarks.html
-rwx------+ 1 803042764 ????????        37343 Jun 22  2008 bookmarks.postplaces.html
-rwx------+ 1 803042764 ????????        40958 May 29  2007 bookmarks.preplaces.html
-rwx------+ 1 803042764 ????????       114688 Jun 12 00:09 cert8.db
-rwx------+ 1 803042764 ????????          417 May 27 10:06 cert_override.txt
drwx------+ 2 803042764 ????????            0 May  2  2007 chrome
-rwx------+ 1 803042764 ????????          180 Jun 11 14:11 compatibility.ini
-rwx------+ 1 803042764 mkgroup-l-d    143302 Jun 11 14:11 compreg.dat
-rwx------+ 1 803042764 ????????         7168 Mar 27 19:03 content-prefs.sqlite
-rwx------+ 1 803042764 ????????       197632 Jun 12 00:09 cookies.sqlite
-rwx------+ 1 803042764 ????????         3627 Dec 10  2008 cookies.txt
-rwx------+ 1 803042764 ????????        96256 Jun 11 15:01 downloads.sqlite
drwx------+ 2 803042764 ????????            0 Jun  9 22:09 extensions
-rwx------+ 1 803042764 mkgroup-l-d       318 Jun 11 14:11 extensions.cache
-rwx------+ 1 803042764 mkgroup-l-d       315 Jun 11 14:11 extensions.ini
-rwx------+ 1 803042764 ????????         1698 Sep 27  2008 extensions.log
-rwx------+ 1 803042764 mkgroup-l-d      3203 Jun 11 14:11 extensions.rdf
-rwx------+ 1 803042764 ????????         6381 Dec 10  2008 formhistory.dat
-rwx------+ 1 803042764 ????????      1093632 Jun 12 00:07 formhistory.sqlite
-rwx------+ 1 803042764 ????????         9848 Dec 10  2008 history.dat
-rwx------+ 1 803042764 ????????          313 Nov 27  2007 hostperm.1
-rwx------+ 1 803042764 ????????        16384 Jun 12 00:09 key3.db
-rwx------+ 1 803042764 mkgroup-l-d     28688 Jun 12 00:09 localstore.rdf
-rwx------+ 1 803042764 ????????        21974 Jun 10 14:24 mimeTypes.rdf
drwx------+ 2 803042764 ????????            0 Dec 11  2008 minidumps
-rwx------+ 1 803042764 ????????            0 Jun 12 00:09 parent.lock
-rwx------+ 1 803042764 ????????         2048 Nov  3  2008 permissions.sqlite
-rwx------+ 1 803042764 mkgroup-l-d    200704 Jun 12 00:10 places.sqlite
-rwx------+ 1 803042764 ????????        62072 Jun 12 00:10 places.sqlite-journal
-rwx------+ 1 803042764 ????????    144270336 Jun 11 23:50 places.sqlite.renamed
-rwx------+ 1 803042764 ????????        11604 Jun 12 00:10 pluginreg.dat
-rwx------+ 1 803042764 ????????       194434 Jun 12 00:09 prefs.js
-rwx------+ 1 803042764 ????????        11351 Jun  4 09:34 search.json
-rwx------+ 1 803042764 ????????         2048 Apr  9 13:26 search.sqlite
-rwx------+ 1 803042764 ????????        16384 Dec 10  2008 secmod.db
-rwx------+ 1 803042764 ????????         1538 Jun 12 00:10 sessionstore.js
-rwx------+ 1 803042764 ????????        11264 Apr  9 12:04 signons.sqlite
-rwx------+ 1 803042764 ????????          466 Dec  8  2007 signons2.txt
-rwx------+ 1 803042764 ????????          882 Jun  8 15:17 signons3.txt
-rwx------+ 1 803042764 ????????      5085184 Nov  7  2008 urlclassifier2.sqlite
-rwx------+ 1 803042764 mkgroup-l-d       154 Jun 12 00:09 urlclassifierkey3.txt
-rwx------+ 1 803042764 ????????         4096 Jun 11 14:10 webappsstore.sqlite
-rwx------+ 1 803042764 mkgroup-l-d     96354 Jun 11 14:11 xpti.dat
$

Comment 2

[Shawn Wilsher :sdwilsh]

It'd be useful to know what add-ons you had installed as well.

Comment 3

[Duncan Loveday]

Attachment: Addons

Extensions: None
Themes: Default
Addons: See attached

Comment 4

[Duncan Loveday]

Do you want me to attach the zipped profile (16M) ?

Comment 5

[Marco Bonardo [:mak]]

Do you use Google Toolbar by chance?
could be bug 489173

Comment 6

[Duncan Loveday]

Yes I do use Google Toolbar but I think there may be something different here as well. That other bug wouldn't explain why one specific group of file:/// URLs would be affected whilst others are not would it ?

The group of URLs where I see slow performance is a set of local disk files used for testing a web application. The testing process has Firefox continually opening and closing popup windows that load those URLs. It's a bit of a stress test for Firefox in a way. I'm wondering if an analysis of the database contents might reveal something interesting.

Anyone know if bugzilla can take a 16M attachment?

Comment 7

[Marco Bonardo [:mak]]

google toolbar due to the above bug will make all history operations a pain. That will explain why in your stress tests you see slowdowns. Page visits and also embed elements visits do use history.
I suggest to either uninstall the toolbar, or try updating it to latest version, Google told they were addressing the issue in the upcoming release. Unfortunatly i've not found a list of "fixes" in current toolbar releases, so i don't know if current release did already fix the issue.

Comment 8

[Duncan Loveday]

(In reply to comment #5)
(In reply to comment #6)
(In reply to comment #7)

Actually I don't use Google Toolbar at all. I use the google search engine - sorry for the misunderstanding.

So it can't be the same issue as bug 489173

Comment 9

[Duncan Loveday]

Attachment: Test case

I can reproduce steady growth of places.sqllite with the attached which emulates the kind of thing my test suite does, continually opening and closing windows to the same small group of URLs.

Comment 10

[Duncan Loveday]

(In reply to comment #9)
> Created an attachment (id=383188) [details]
> Test case
> 
I'd hoped this could be run live in the bug using jar:https://bug497732.bugzilla.mozilla.org/attachment.cgi?id=383188!/bug497732/test.html but I can't get it to work. Failing that, unpack the jar in a temporary directory and open test.html. Note the size of your places.sqllite, then press "go" a few times. Note the size again - it will be bigger and keep on getting bigger the more you run it.

Options must be set to allow popup windows to open.

Comment 11

[Dietrich Ayala (:dietrich)]

duncan, what does your testcase do? is it just a matter of creating lots of visits?

wrt your initial comment #0, the fact that changing the location of the file (eg: file has no history), it could be that the slowdown is due to checking to see if links are visited or not. do those files have any links in them?

Comment 12

[Duncan Loveday]

Not sure what (precisely) constitutes a visit. The test case continually opens and closes popups that load the same small group of html files. It follows the sequence below. Over a period of months this seems to have produced a very large places.sqllite as if something is accumulating in it. My real files do have some links in them, to local html files and "javascript:" functions.

1 Load test.html in window w, choose number of repetitions n, press "Go".
2 Open popup 1, load test2.html.
3 Load event fires for test2.html, opens popup 2, loads test3.html
4 Load event first for test3.html, calls back to popup 1 using opener.
5 Popup1 closes popup2, calls back to window w using opener.
6 Window w decrements a count and schedules a reload of popup1 using setTimeout.
7 Sequence repeats from 2 until the count reaches zero.

In real life, each repetition is the execution of a test case for a web app.

Comment 13

[-]

Sorry to intterupt yet...

First of all, for privacy reasons you shouldn't be offering your places.sqlite even for a good cause. And secondly until now I considered myself to have a "large" places.sqlite of 15M size with 20K entries within. Yet thanks to you now I think this is acceptable...

As a casual user I think your case simply tests either SQLite itself of Firefox's implementation of SQLite versus large entries but not the Firefox. I believe you should first find that if SQlite with your number of entries can perform OK...

I suggest you to use history block/delete addons in conjunction with SQLite editors like "SQLite Expert" to keep your places.sqlite in good/slim shape and "vacuum"ed, since until vacuum, all deleted entries still is there yet not attached causing bloat. Also some history block addons doesn't interfere with simple back/forward button functionality allowing you to back/forth without ever growing history and its consequences...

These are practical suggestions yet I myself wonder what lies beneath?...

Comment 14

[Marco Bonardo [:mak]]

if this slowdown is driven by history, can just be dupe of bug 223476

Comment 15

[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 16

[Ken Johanson]

I can supply a places.sqllite that makes this ONE HUNDRED PERCENT reproducible in ff 3.6.3, where immediately upon opening FF, VM size jumps to +500MB. 

Further, deleting places.sqllite (and reimporting the JSON backup I just made) fixes the problem for about a week (at my particular browsing voracity). But eventually as places.sqlite grows, the memory (VMSize in taskman) grows to well over 500MB even 1000MB (even when places.sqlite is just 2.5 MB!). 

Further, Tools->Clear Recent History->[All] + [Cache] && [Browsing+Download] history, then restarting FF STILL does not lower the mem use following a FF restart.

Additionally, I have tried disabled EVERY plugin + extenion and the mem use did not lower after restarting FF.

___ONLY CREATING A NEW PLACES.SQLLITE____ file effects a temporary fix.

My machine has 2GB so almost does "OK" (firefox being the major consumer of mem). Wife's laptop has 500MB and suffers from severe paging, making the browser unbearable. I'm certain that many, many others users of FF must be affected by this, it should be rated a SEVERE bug. Again I can provide places.sqllite file to make it verifiable for devs.

Comment 17

[Dietrich Ayala (:dietrich)]

Thanks Ken, and my apologies for this problem! Can you email it to [e-mail]?

Comment 18

[Ken Johanson]

Dietrich, I emailed you on Apr 12 from 'ken2006 at kensystem-com', please let me know if you received that or perhaps it was placed in a spam folder. Thanks!

Comment 19

[Marco Bonardo [:mak]]

Hi, could you pleease upgrade to Firefox 4 and check if performance will improve (please try for some days before commenting, since FF4 does also some additional cleanup at idle times)

Comment 20

[Duncan Loveday]

I have been on Firefox 4 since it was released (actually had some nightlies before that also).

I re-ran the test case attached to this bug and saw no increase in size of any of my .sqlite files. These sizes are below.

However I would not say the performance was that great. It is very stop-start in nature - some long pauses - and Firefox used a great deal of CPU time, over 60 seconds for 100 iterations in the test case.

Suggestion: Improve the test case to capture timing information then re-run on versions 3.0 and 4 to compare the times.

-rwx------+ 1 803042764 ????????   262144 May  2 12:17 addons.sqlite
-rwx------+ 1 803042764 ????????    98304 Apr 30 15:23 chromeappsstore.sqlite
-rwx------+ 1 803042764 ????????   229376 Apr 22 00:24 content-prefs.sqlite
-rwx------+ 1 803042764 ????????   524288 May  3 10:23 cookies.sqlite
-rwx------+ 1 803042764 ????????    65536 May  3 10:12 downloads.sqlite
-rwx------+ 1 803042764 ????????   393216 Apr 30 15:23 extensions.sqlite
-rwx------+ 1 803042764 ????????   163840 May  3 10:23 formhistory.sqlite
-rwx------+ 1 803042764 ????????    65536 Mar 31 12:31 permissions.sqlite
-rwx------+ 1 803042764 ???????? 20971520 May  3 10:23 places.sqlite
-rwx------+ 1 803042764 ????????    65536 Apr 30 15:23 search.sqlite
-rwx------+ 1 803042764 ????????   294912 May  3 10:23 signons.sqlite
-rwx------+ 1 803042764 ???????? 36700160 Mar 31 12:31 urlclassifier3.sqlite
-rwx------+ 1 803042764 ????????    98304 Apr 18 17:13 webappsstore.sqlite
$

Comment 21

[Duncan Loveday]

BTW I believe comments #16 to #18 are not the same issue. They're about a different version of Firefox and describe different symptoms.

Comment 22

[Duncan Loveday]

Attachment: Test case with timings

Comment 23

[Marco Bonardo [:mak]]

So if I understand this correctly, in Firefox 4 the database size does not increase that much as in 3.x, the performances are slightly better but still lagging sometimes.
I guess if this is really a history problem or a GC problem due to history observers.
I'm assigning the bug to myself to remember to run these tests and check which kind of traffic we generate.
Btw, conider that a 20MB places.sqlite is not large, mine is more than 100MB.

Comment 24

[Duncan Loveday]

> the database size does not increase that much as in 3.x

It didn't increase at all. Not a single byte. Whereas when I ran the test in 3.0 it increased steadily. So that part is definitely better.

> the performances are slightly better but still lagging sometimes

I have not compared performance of 3.0 vs 4 in this regard. Performance in 4 was definitely suffering from frequent pauses and took over 60 seconds for 100 iterations.

Just now I set firefox 4 to "never record history" and the test ran much faster - 20 seconds or so - and memory use was also much less, about 200M as compared to 600M. But now I've set it back to recording history and it hasn't gone back to the 60 seconds I saw earlier. Still around 20 seconds and 200M. Whether that's because turning off history has cleared something out or something unrelated I don't know.

Comment 25

[Marco Bonardo [:mak]]

I checked what happens when we open these popups.

In history.disabled mode for each popup:
- we query for the bookmarked status of the page, this happens since the popup shows the locationbar, included the star

In normal mode for each popup:
- we query for the bookmarked status of the page, as above
- we insert a visit to the page

Now, all of this is asynchronous and happens on a separate thread, I see no timing difference between doing 100 runs with history disabled or 100 runs with history enabled, but I have a multi-core cpu.
A simple fix may be to cache the last requests, but I'm not sure it's worth it, since it would only help in these benchmark-like cases, that is not something we are really interested in improving. We prefer doing real improvements that may actually be hit by users.
The best direction is to limit the queries traffic. Some of the work can be reduced by moving to a new schema, some by switching all APIs to be async. I'm currently looking if there is some optimization we can do immediately though.

Comment 26

[Duncan Loveday]

> I'm currently looking if there is some optimization we can do immediately though

Excellent, looking forward to that.

Running the test case with 100 iterations on Fx 7.0.1 and history enabled just now took 26 seconds. There are short but noticable pauses in the processing.

Comment 27

[Marco Bonardo [:mak]]

Pauses may also be caused by GC, as in any other test that does things in a loop, the garbage collector may take some time. The new generational GC will help that, once available. Btw, I don't want to go OT.

Comment 28

[Rajesh]

ghgf hghgh

Comment 29

[Wayne Mery (:wsmwk)]

(In reply to Marco Bonardo [:mak] from comment #27)
> Pauses may also be caused by GC, as in any other test that does things in a
> loop, the garbage collector may take some time. 

installing about:jank might help confirm that


> The new generational GC will help that, once available. Btw, I don't want to go OT.

as in bug 619558?  doesn't seem to have gotten far in the past year

Comment 30

[Wayne Mery (:wsmwk)]

(In reply to Wayne Mery (:wsmwk) from comment #29)
> (In reply to Marco Bonardo [:mak] from comment #27)
> Pauses may also be
> caused by GC, as in any other test that does things in a
> loop, the garbage
> collector may take some time. 

installing about:jank might help confirm

correction: MemChaser 
https://addons.mozilla.org/en-US/firefox/addon/memchaser/

Comment 31

[Marco Bonardo [:mak]]

This bug is no more useful as is, we need separately filed bugs with ways to reproduce them or profiler stacks