Monday, December 7, 2009

Nailed Browser Performance Issue

I may have finally nailed a performance issue that I have been having with FireFox for a while now. I keep updating and hoping that it will go way. While I am using the browser, it stops responding for a second or two periodically. When the system is really loaded, it gets even worse. I spent some time lurking around the web looking for solutions. I have tried disabling some things. I have tried lots of stuff. Today, I was getting even more frustrated and tried searching again. In the past, I was running into trouble with the Google toolbar's start screen. It turns out that there is, or at least was, a bug where the SQLite DB would grow and grow. The system would keep updating it. As the DB grew, your profile would get huge and each update would take longer and longer. My TimeMachine backups were huge. I would have 250MB of changes in seconds. If I ran a backup and then immediately ran another backup, whammo 250MB. I decided to find out what was being backed up during that period of time. I found and tried Grand Central. Grand Central provides a view of the file system based on disk usage. Files are graphically displayed sized in proportion to their size on disk. Once the system spent a little while churning on the disks, I could see what file was taking up most of the 250MB. There were many many large blocks that included places.sqlite I believe. Googling for this resulted in a description of the FireFox slowdown I was having, along with an easy fix (download the SQLLite manager and truncate the right table). I have also turned off the Google start page which avoids the problem all together.

Today, I was getting more and more annoyed with my current slowdown. It is not as bad as the other one (30 seconds of beach ball of death, 5 seconds of work, rinse and repeat). I have noticed that the system writes and reads from the disk quite a lot but I have not been sure what it is doing. LSOF is a difficult way to catch something that transient. The new slowdown is a fraction of a second complete pause in FF. Depending on system load and CPU it might be more or less often or slightly longer. I actually thought it was Flash missbehaving at first. Anyways, in today's search for FF pauses, I found a website for an ISV: They talk about pauses and mention monitoring the file system with fs_usage several pages down. I tried this and was flooded with file system messages.
sudo fs_usage -f filesys

Lots and lots of messages. FF was one of the major contributors. I piped the output to a file and tried using tail in another shell to monitor the disk activity.
sudo fs_usage -w -f filesys > biglog.txt

tail -f biglog.txt

Unfortunately, tail was causing a flood of messages of its own. Way more than the actual traffic. Without tail, it was hard to figure out what was happening. The biglog file was 150MB and many of the commands and filenames were chopped. I tweaked the parameters to fix that '-w' and hone in on FF.
sudo fs_usage -w -f filesys firefox-bin > biglog2.txt

Now I have a list of just FF is doing. I started using the program, waited for the hiccup, and immediately hit ctrl-c in the shell window. The log contained lots and lots of line items. Lots of seeks, truncates, ... There was only one file name mentioned however:
es/Firefox/Profiles/23oitqok.default/Google Gears for Firefox/permissions.db-journal

I quickly disabled the add-on and restarted FF. Once restarted FF no longer exhibits the issue that I was seeing before. While writing this article, I looked on my disk for the file. I wanted to see how big the file is/was. I could not located it. I also could not locate it on the backup. After finding the documentation for the Gears API, I was able to locate the files. Thanks to Google for documenting all of the file locations for every OS and browser combination. All of the files are small. I am not sure why the journal would be big, but it is gone now. I don't know how big it was and I cannot find the file in TimeMachine.

On a positive note, my system has not had a single hiccup since I disabled the add-on. I can live with a slight mystery without the odd pauses. Also, during my search for the file I could not locate, I was performing find commands over large portions of my HDD, specifically:
find . -name "permissions.db-journal"

This reasonable amount of disk activity did not cause the browser to hiccup at all. I am impressed, I thought the system was very susceptible to HDD activity based delays. It might have been only HDD activity was slowing down the blocking HDD activity the browser was trying to get done.