Category Archives: Start Faster

Diagnosing a Talos ts_paint regression on Windows XP

Recently, I worked on diagnosing a 3% startup time regression in the Talos ts_paint benchmark and I thought I’d share my experience with others who might be dealing with a similar regression.

Procedure

My first step was to reproduce the regression on a Windows XP machine under my control. To prep the machine, I turned off unneeded background services to prevent them from interfering with measurements, created new Firefox profiles, configured Firefox to stop checking for updates and to use a blank page as its homepage, disabled extensions (that had been installed system-wide), and launched Firefox several times so that any data needed from disk during startup would be cached (ts_paint measures “hot” startups). I also wrote a batch script to automate the launching and shutting down of Firefox so that I could easily collect data from dozens of startups.

Finally, I turned on Telemetry data gathering since Telemetry records timestamps for each startup phase. During Firefox exit, Telemetry writes the collected data as a JSON file in <profile directory>\saved-telemetry-pings\, so every time I launched & shut down Firefox, it would spit out a new JSON file containing the startup timings. You can see a list of the startup times collected by Telemetry in the “Simple Measurements” section of your Firefox’s about:telemetry page.

I then wrote a simple Python script to extract and format the startup data from the Telemetry JSON file. This is the script and these are the results in a Google Docs spreadsheet. The regression is highlighted in red in the spreadsheet. The times show surprisingly little variation between runs and suggest that the regression is entirely contained in the startup phase directly preceding the first paint of a Firefox window. Luckily, the Gecko profiler has already been initialized at this point of startup so it was possible to capture profiles of the browser’s activity. Matt Noorenberghe and Mike Conley were able to show that at least part of this regression is caused by initialization of the new “Customize UI” functionality and painting of tabs inside the titlebar (bug 910283).

Problems profiling on Windows XP

I first tried profiling the startup regression with XPerf and I soon discovered that setting up XPerf on Windows XP s a surprisingly cumbersome task. I had to install XPerf from the Microsoft Windows SDK for Windows Server 2008 on a different computer running a more modern, 32-bit version of Windows (XP wouldn’t work, I used Vista), and then I manually copied xperf.exe onto the Windows XP machine. Unfortunately, I found that it’s not possible to profile with stackwalking enabled on XP and also that the captured profiles can’t be examined on an XP machine, requiring yet more copying to a newer Windows machine.

I also found that the pseudo-stack and native stack frames were not being interleaved properly in the Gecko Profiler on Windows XP (bug 900524). This was particularly irksome since it meant the JS and C++ stacks would not be merged correctly. It turned out that the version of StackWalk64 that shipped with dbghelp.dll in Windows XP was not walking the data stack properly and that replacing it with a newer version from Debugging Tools for Windows resolved the problem.

A quick Firefox startup update

Recently I’ve been working on a project to improve desktop Firefox’s startup time during “cold starts” where none of the Firefox binaries or data are cached in memory (e.g. the first launch of the browser after a reboot). I’ve been paying special attention to the time required to reach the “first paint” startup milestone: the point in time when the first Firefox window becomes visible.

The analysis has mostly consisted of profiling the latest Firefox Nightlies using XPerf on a reference dual-core Windows 7 laptop with a magnetic HDD. I’ve been working on several bugs arising from the investigation (bug 881575bug 881578, bug 827976bug 879957, bug 873640) and I have many more coming. This is an overview of a few challenges I’ve run into over the last month.

Making Startup Times Reproducible

I wanted to evaluate the impact of my experimental code changes by comparing startups, but I quickly discovered that there is a tremendous amount of variation in startup times in my test environment. I then turned off Windows Prefetching & Windows SuperFetch, two performance features responsible for pre-fetching files from disk based on the user’s usage patterns, but I still recorded excessive variation in start times.

I then turned off a plethora of 3rd-party and Windows services that were running in the background and accessing the disk: Windows Update & Indexing Service, OEM “boot optimizer” software, Flash & Chrome automatic updaters, graphics card configuration & monitoring software bundled with drivers, etc. After rebooting the laptop several times and disabling any remaining programs causing disk activity, I was finally able to achieve reproducible startup times. I expected that cold starts would be dominated by disk I/O, but I was suprised by just how heavily I/O operations dominated startup time in a vanilla Firefox install.

Startup time has improved almost 30% over the last year

In an attempt to reproduce the startup regression reported in bug 818257, I compared time to first paint for Firefox 13.0.1 and Firefox 21.0 using my test setup. To my surprise, I found Firefox 21.0 (current release channel) requires roughly 4.6 seconds to reach first paint during cold starts, while Firefox 13.0.1 (release channel from a year ago) required ~6.4 seconds! This is almost a 30% reduction in startup time.

See the raw results from 5 runs in a Google Docs spreadsheet here

I was surprised by this result because I expected increases in code size and the overhead from initializing new components added over the course of a year to cause regressions in startup. On the other hand, many people have landed patches to improve startup by postponing component initialization and generally reducing the amount of work done before the first-paint milestone. I haven’t tried to identify the patches responsible yet, but from a quick look at the XPerf profiles for each version, it looks like there were gains from fixing bug 756313  (“Don’t load homepage before first paint”) and from changing the list of Mozilla libraries pre-loaded at startup (see dependentlibs.list).

We are still FSYNC-ing too much at startup

Apparently, the FlushFileBuffers function on Windows causes the OS  to flush everything in the write-back cache as it “does not know what part of the cache belongs to your file”. As you can imagine, calling FlushFileBuffers is bad news for Firefox startups even it’s done off the main thread — other I/O requests will be delayed while the disk is busy writing data. Unfortunately we are currently calling this method on browser startup to write out the webapps.json file, the sessionstore.js file, and several SafeBrowsing files. The flush method isn’t being called directly, rather it’s the SafeFileOutputStream and OS.File.writeAtomic() implementations that force flushes for maximum reliability. In general, we should avoid calling methods that fsync/FlushFileBuffers unless such reliability is explicitly required, and I’ve asked Yoric to change OS.File.writeAtomic() behavior to forego flushing by default.

Next steps

I’m continuing to work on reducing the number of DLL loads triggered at startup and I’ll soon be filing bugs for fixing some of the smaller sources of startup I/O.