One of the things that we at Mozilla would like to do better at is the amount of time it takes between when you launch Firefox, and when it starts up and is usable. We've been tackling this problem for quite a while, and have already made tremendous improvements. But we think we can still do better.
Last week, Vlad landed the function timer API, which can be used for producing a log of how much time it takes to execute any given code block. This is a very useful framework for measuring how much time different things consume at Firefox startup. On Monday, I, Vlad, Shawn, Johnathan, and Shaver started to look into instrumenting Firefox to produce a useful log of what goes on at Firefox startup, to be able to analyze it to identify the areas that we're being slow at, in order to focus our attention to improve those pieces of code.
I set up a clone of mozilla-central here to so that we can focus on adding probes to the code without being slowed down by trying to lands things on mozilla-central for now. Then, we started to add probes like crazy. The probing work is really finished now, and I think that we'll spend some time tomorrow to try to analyze the logs, in order to be able to make some sense out of them, and identify the areas where we can attack in order to get the most gain in reducing the startup time.
If you want to create your own startup logs, here are the steps to do that. Please note that these instructions are for Windows. Other platforms can be measured similarly, but we're trying to focus our attention to Windows for now.
- Clone the repository.
- Your measurement would be most useful if you create a build similar to our release versions of Firefox. In order to do that, you can grab a copy of the mozconfig file which we use for our release builds. Make sure that you add ac_add_options –enable-functiontimer so that your build actually includes the probes, and remove the --enable-update-channel and --enable-update-packaging options, to make sure that you don't mess with the release update channels.
- Build firefox, and create an installer:
make -f client.mk build
make -C objdir package
make -C objdir installer
- Go to objdir/dist/install/sea, you will find a file named something like firefox-3.7a5pre.en-US.win32.installer.exe there. This is a normal installer. Use that to install this version of Firefox somewhere on your system. Please note that you don't want to replace this with your default Firefox install, since it's built from a random revision off of mozilla-central, and it's subject to all the usual warnings when running experimental builds.
- Set the MOZ_FT environment variable to the full path of a file which will be used as a log file, for example: C:\Users\ehsan\startup.log.
- Execute the installed version of Firefox. As soon as you see the window on screen, type an address like mozilla.com inside the location bar, press enter, wait for the page to load, and then close Firefox.
- Open the log file you specified in step 5. Try to find the address that you entered in step 6 in that file. Anything before the first occurence of the address is what happened before Firefox started up and became usable on your system.
Here is a bit of information about the format of the log. On each line, you will see a pattern like this:
[ 123.45] > ( 5) |nsContentDLF::CreateBlankDocument (line 349)
[ 244.43] ***** ( 2) | 0.50 ms ( 0.65 ms total) - NS_InitXPCOM3_P (line 480) [Next: timer startup]
[ 330.21] < ( 10) | 3.48 ms ( 3.48 ms total) - mozJSComponentLoader::Import (line 1444) (file: resource://gre/modules/XPCOMUtils.js)
Here is what each of these items mean:
- Time stamp in ms. This is the time passed since Firefox was started when this message was being added to the log.
- >, *****, or <. These include three types of logs: function entry, function marker, and function exit, respectively. The first and last ones are obvious. The function marker is used for a few very large functions in order to enable us split up the function's execution time in chunks, so that we can know how much time a function took to execute.
- Call nesting depth. It is a number indicating the depth of the call. It can be used to show whether a function has been called (directly or indirectly) by another one.
- Function name and line number. It shows the function in which the log was recorded, and which line in the respective source code it has been defined on.
- Elapsed time and total time. These two numbers show how much time has been elapsed inside the function, and how much total time the function has been executed so far. Note that these numbers are not applicable to function entries. Also, note that they will be equal on function exit, because the log is generated as the last step inside the function.
- Marker identifiers. These are only used for function markers, and usually show what is going to happen next inside the function.
- Extra information. Some of the log lines have some extra information associated with them. For example, the third line in the sample above shows that the module being loaded was XPCOMUtils.js.
Johnath has also adapted a script to generate graphs from the logs, but at this point, we're thinking that the graphs are misleading, and therefore I'm not going to talk more about this, but check the bug for more information (including how to create such graphs, and some graph samples.)
The next steps probably include finding out where there are gaps in our logs, and try to add probes to cover those areas. We also need to generate logs for a range of different profiles, including blank and heavy ones. We need to generate a variety of logs to ensure that we're not missing any obvious use case of Firefox. We are also trying to figure out which types of visualizations for this data would be helpful, to be able to better filter/present the generated logs. Hopefully, we'll soon have a number of actionable tasks which we can pursue to reduce Firefox startup time to a significant degree.
If you have any ideas how to improve things, or have any logs which we need to see, either comment here or in the bug.