418166 - Long sqlite database shutdown times + 100 % CPU on browser exit

Status: VERIFIED DUPLICATE of bug 415201

(Firefox :: Bookmarks & History, defect)

Description

[IU]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9b4pre) Gecko/2008021704 Minefield/3.0b4pre
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9b4pre) Gecko/2008021704 Minefield/3.0b4pre

Fx 3's sqlite engine takes a long time to close its database.  This is very noticeable on slower machines (P3 933 MHz, 512 MB), resulting in long shutdown times.  During this time, CPU utilization is also at or near 100 %; however, disk activity is not high, suggesting the problem is mostly CPU (maybe also memory bandwidth) bound.

For instance, my places.sqlite database file is only 2.13 MB in size, but, during the browser shutdown process, it normally takes Firefox 5 to 7 seconds (1.5 to 2 seconds in safemode) to close it.  The result is that shutdown is taking about 13 seconds on average.

The patch for Bug 415201 significantly reduced the contribution due to the bookmarks issue; however, overall shutdown time for me is still high.

I used SysInternals Process Monitor to watch the shutdown process.  The following are sample excerpts of the relevant sections (edited for compactness):

SAMPLE  #1
6:52:04.1131147 PM  firefox.exe	UnlockFileSingle  C:\...\places.sqlite	SUCCESS
6:52:04.1134257 PM  firefox.exe	CloseFile  C:\...\places.sqlite	SUCCESS	
6:52:10.8500646 PM  firefox.exe	ReadFile  C:\Program Files\...\Firefox\xul.dll	SUCCESS

SAMPLE #2
9:43:11.8489936 AM  firefox.exe  UnlockFileSingle  C:\...\places.sqlite  SUCCESS
9:43:11.8493040 AM  firefox.exe  CloseFile  C:\...\places.sqlite  SUCCESS	
9:43:16.6432297 AM  firefox.exe  CloseFile  C:\...\permissions.sqlite  SUCCESS	

Oddly, in one test, my places.sqlite database shutdown was fast, but the downloads.sqlite database (only 12 KB) was slow (about 8 seconds).  Even so, the shutdown still took 13 seconds, as though whatever the database engine is doing to contribute the delay was performed earlier in the process. See sample below:

SAMPLE #3
3:41:19.0439632 PM  firefox.exe  CloseFile  C:\...\downloads.sqlite  SUCCESS	
3:41:26.9535749 PM  firefox.exe	CloseFile  C:\...\permissions.sqlite  SUCCESS	
[...]
3:41:27.2271432 PM  firefox.exe	UnlockFileSingle  C:\...\places.sqlite  SUCCESS
3:41:27.2274555 PM  firefox.exe	CloseFile  C:\...\places.sqlite  SUCCESS	
3:41:27.2291052 PM  firefox.exe	CloseFile  C:\WINDOWS\WinSxS\x86_Microsoft.Windows.Common-Controls...  SUCCESS	

Unfortunately, I cannot provide my profile for inspection.  This is a regular profile I use daily.  I have 68 extensions installed (14 or these disabled).  I do not have an active virus or malware scanner.

Reproducible: Always

Steps to Reproduce:
1. Use a slower (sub 2 GHz system to test)
2. Launch Fx 3 using a regular, daily used profile
3. Launch Microsoft/Sysinternals Process Monitor and filter on the firefox.exe process
4. Shutdown Fx and inspect the Process Monitor log
Actual Results:  
Browser shutdown is very slow: contributed, it appears, by the sqlite database engine.

Expected Results:  
It should not take as much as 8 seconds to close a 12 KB database file.

System specs (yes ancient :-)

Intel 815E chipset
P3 933 MHz
512 MB PC133 RAM
Windows XP Pro, XP2
ATA100 hard disk

Comment 1

[Ondrej Brablc]

This could be related to bug 416988.

Comment 2

[Martijn Wargers (dead)]

Does the problem also occur without any extensions involved?

Comment 3

[IU]

(In reply to comment #2)
> Does the problem also occur without any extensions involved?
> 

After doing a lot of testing testing, I see there is a correlation between the number (not quality) of extensions installed (plus number of tabs) in the closing delay of places.sqlite.  I have additional data points, but I think this is enough to show the pattern:

1. 54 extensions enabled, session resuming disabled: 6.8 sec shutdown (3.2 sec for places.sqlite)
2. All but default extension disabled: 3 sec (0.7 sec for places.sqlite)
3. 3 extensions enabled: 3.2 sec (1.1 sec for places.sqlite)
4. 11 extensions enabled: 4.2 sec (1.5 sec for places.sqlite)
5. 30 extensions enabled: 5.3 sec (2.5 sec for places.sqlite)
6. 50 extensions enabled: 6.4 sec (3.7 sec for places.sqlite)
7. All 54 extensions reenabled: 6.4 sec (3.4 sec for places.sqlite)
8. Reenabling session resuming did not make any meaningful difference
9. 54 extensions, resuming enabled, two windows, 16 tabs: 8.8 sec (4.8 sec for places.sqlite)
10. 54 extensions, no resuming, 5 windows, not tabs: 8.5 sec (4.8 sec for places.sqlite)
11. Per #10, using browser a bit then shutting down before typing this line: 11.3 sec (7.5 sec for places.sqlite)
12. Repeat shutdown shortly after: 9.1 sec (5 sec for places.sqlite)

Comment 4

[IU]

(In reply to comment #1)
> This could be related to bug 416988.
> 

Difficult to say, though possible.  I'm a little suspicious of the check-in for Bug 415201.  Before that check-in, the delay was distributed over the bookmarks.postplaces export operation.  There was no delay in closing places.sqlite.  After that check-in, the bookmarks.postplaces operation takes only 1 second, but the magnitude of delay remains and is now concentrated primarily on closing places.sqlite.  It's like the problem got shifted to the end.

Comment 5

[Mike Beltzner [:beltzner, not reading bugmail]]

Tony: can we get some QA resource looking into shutdown times to see if we can confirm this? Maybe co-ordinate with Dietrich? I think you guys have some large places DBs to use for this sort of testing ...

Comment 6

[Martijn Wargers (dead)]

IU, how do you get those numbers in comment 3?

Comment 7

[IU]

(In reply to comment #6)
> IU, how do you get those numbers in comment 3?
> 
I use Process Monitor: http://technet.microsoft.com/en-us/sysinternals/bb896645.aspx

And this is the method I use:

1. Launch Windows Task Manager
2. Launch Process Monitor then select the menu: Filter --> Filter...
3. Add this filter: Process Name| is |firefox.exe | Include
4. Now everything else will be excluded by default.  Note: All settings persist
5. Make sure Autoscroll is disabled (the toolbar button to the right of the magnifying glass).
6. Initially, also double-check that "Show Registry Activity", "Show File System Activity", and "Show Process and Thread Activity" (the 3 right-most toolbar buttons) is enabled
7. On Firefox, click the File menu to flush out some activity (visible on Process Monitor)
8. Wait a couple seconds
9. Click the "Clear" button on Process Monitor then quickly go and File --> Exit Firefox before any other events occur.
10. Wait till the Firefox process completely exits (Windows Task Manager).
11. On Process Monitor, freeze capturing (magnifying glass toolbar button) and examine the output.

Comment 8

[Tracy Walker [:tracy]]

Mike, Tchung:  Ill try to confirm. I've got a relatively slow Windows XP box here. 

IU, can you provide the size of the places.sqlite?  History and Bookmarks size as well? 

I'll try with clean profile. Then dirty one up with a bunch of extensions.  I have a profile with a ridiculously large history and bookmark set. But it's proven to be a Fx3 crusher (iirc, larger than our defined limits)

Comment 9

[IU]

(In reply to comment #8)
> IU, can you provide the size of the places.sqlite?  History and Bookmarks size
> as well? 
> 
places.sqlite: now 2.83 MB
History: currently 2833 entries
Bookmarks: 1049 link entries, 26 root folders and various child folders (299 total folders).
bookmarks.postplaces: 470 KB

Comment 10

[Tracy Walker [:tracy]]

my XP system is 2. GHz with 1 GB ram. I have a places.sqlite that is 43,366 KB which contains about 30,000 bookmarks all in the bookmarks menu and 30,000 history visits.  Yeah it was created by bc's spider and he had it bookmark every page visited.  It takes ~25 seconds to shut down the firefox.exe process on File > Exit. It doesn't suck all the cpu but does spike high and waver up and down. Anyway, I think this test profile goes beyond what our supported limits are set to.

note: with a clean profile, shutdown takes about 2 seconds.

Comment 11

[Ondrej Brablc]

(In reply to comment #10)
> my XP system is 2. GHz with 1 GB ram. I have a places.sqlite that is 43,366 KB
> which contains about 30,000 bookmarks all in the bookmarks menu and 30,000
> history visits.  Yeah it was created by bc's spider and he had it bookmark
> every page visited.  It takes ~25 seconds to shut down the firefox.exe process
> on File > Exit. It doesn't suck all the cpu but does spike high and waver up
> and down. Anyway, I think this test profile goes beyond what our supported
> limits are set to.
> 
> note: with a clean profile, shutdown takes about 2 seconds.
> 

1) What is the size of your bookmarks.postplaces? 
2) Do the collected bookmarks often have annotations (description or keywords)?

Comment 12

[Tracy Walker [:tracy]]

1) What is the size of your bookmarks.postplaces?  
 it's 9KB, I copy the large places.sqlite and replace the default
2) Do the collected bookmarks often have annotations (description or keywords)?
 no, not that I know of.  They are just plain bookmarks, no added keyword or description

Comment 13

[Dietrich Ayala (:dietrich)]

Note that when bug 384370 is fixed:

1. bookmarks backup will only occur once every 24 hours, instead of at every shutdown

2. it can occur while idle, so might not happen at shutdown at all depending on users usage pattern

3. man, how long did this take before bug 415201 was fixed?! probably minutes!

Comment 14

[Martijn Wargers (dead)]

(In reply to comment #13)
> Note that when bug 384370 is fixed:
> 
> 1. bookmarks backup will only occur once every 24 hours, instead of at every
> shutdown

Will the fix for bug 384370 make things quicker or slower?

> 2. it can occur while idle, so might not happen at shutdown at all depending on
> users usage pattern

It seems that this will mean that people could potentially get 'strange' hangs on random times.

Is there a minimum performance requirement? Like suppose you have a computer with an 800MHz CPU and you have 2000 bookmarks, how long should it take at maximum?
Note that I would prefer it if the performance would not be worse than Firefox 2 in this case.

Comment 16

[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