performance: runtime tracing

A key element in any performance effort is getting specific, quantifiable measurments about what is going on. Tools called profilers often do this by inserting bits of code into (or instrumenting) a program. This instrumentation code starts and stops a timer, and accumulates the amount of time spent performing certain events.

Unfortunately, most profilers are (1) very expensive (and therefore unavailable to the mozilla.org community at large), and (2) not good at handling asynchronous processing (which Mozilla is currently chock full of). So we decided to build our own little instrumentation library that would help developers gather timing statistics for coarse grained events like network traffic.

This page describes how to run Mozilla to collect data and how to instrument Mozilla code to gather your own statistics.

We are currently in the process of building the mother of all performance databases for Mozilla. We want to take "normal" browsing sessions and rip them apart, both at a detailed page-by-page level to identify specific sites that cause Mozilla to suck, and at an aggregate "10,000 foot" level to identify content trends that cause Mozilla to suck. Here is how you can help.

Mozilla binaries (as of August 10, 1998) contain code that will dump out timing information to a log file when certain environment variables are set. Setup your environment to turn tracing on, run the browser normally, and send us the log file. Here are the details:

1. Enable Logging. First, you need to tell Mozilla (or Gromit) to start collecting performance statistics:

   Win32. In c:\autoexec.bat (on Win95) or System Properties/Environment (on Windows NT), set the NSPR_LOG_FILE environment variable to c:\tmp\nspr.log (or something else that you'll remember). Set your the NSPR_LOG_MODULES variable to nsTiming:5.

   Unix. As with Win32: set NSPR_LOG_FILE to /tmp/nspr.log, set NSPR_LOG_MODULES to nsTiming:5.

   Mac. Coming soon.

   This will work in debug and optimized builds.

2. Run Mozilla. Now, each time you run Mozilla, a file called nspr.log (or whatever you chose to name it) will be created. This file will contain some horrid-looking information that is not really meant for human consumption.
3. Mail the log to perfstat@zeeb.mcom.com. Take the log file and attach it to an email. When the performance server receives the mail, it will run a script to load your logfile into the database. This will take a while, depending on how big the log file is, etc. We don't currently have any good feedback mechanism (like a response, that says "I'm done"), but we're working on it...

Note that the log file will get clobbered each time you restart the browser. So copy it or rename it if you don't want to mail it out right away.

So there's something that you want to time? Here's how to do it:

1. Add #include "timing.h" to your file: mozilla/include/timing.h contains a couple of fairly simple macros that you can use to start and stop "clocks" that are associated with individual events.
2. Use one of the following macros to start a "clock" that will be associated with your event:

   • TIMING_STARTCLOCK_OBJECT(char* op, void* obj). This creates and starts a "clock" that is uniquely identified by the named operation op and the pointer obj. The clock should be stopped using TIMING_STOPCLOCK_OBJECT().

   • TIMING_STARTCLOCK_NAME(char* op, char* name). This creates and starts a "clock" that is uniquely identified by the names operation op and the string name. The clock should be stopped using TIMING_STOPCLOCK_NAME().

   "Starting a clock" involves noting the current system time, and inserting an entry into a table.

3. Use the corresponding macro to stop a "clock" and print out a message to the timing log:

   • TIMING_STOPCLOCK_OBJECT(char* op, void* obj, void* cx, char* msg). Stops a clock that was started using TIMING_STARTCLOCK_OBJECT(). This prints a message into the log of the form:

     timestamp: clock,op,obj,elapsed,cx,msg
     

     Where op is the "operation" string used to identify the timer, obj is the 32-bit hexadecimal value of the object pointer, elapsed is the elapsed time in microseconds, cx is a 32-bit hexadecimal context (usually the MWContext structure), and msg is the message string. For example:

     TIMING_STOPCLOCK_OBJECT("lo:blk-tab", lo_ele, cx, "ok")
     

     would result in an entry like this in the log:

     19980810.104233.250000: clock,lo:blk-tab,6abde0,2340000,6bd000,ok
     

   • TIMING_STOPCLOCK_NAME(char* op, char* name, void* cx, char* msg). Stops a clock that was started using TIMING_STARTCLOCK_NAME(). This prints a message into the log of the form:

     timestamp: clock,op,name,elapsed,cx,msg
     

     Where op is the "operation" string used to identify the timer, name is the character string name used to identify the clock, elapsed is the elapsed time in microseconds, cx is a 32-bit hexadecimal context (usually the MWContext structure), and msg is the message string. For example:

     TIMING_STOPCLOCK_OBJECT("dns:lookup", hostname, cx, "ok")
     

     would result in an entry like this in the log:

     19980810.104526.750000: clock,dns:lookup,www.frobaz.com,41000,6bd000,ok
     

That's it. If you want to take a look at some examples, grep through mozilla/network/main, mozilla/network/protocols/http, and mozilla/lib/layout for starters. The actual implementation of the timer functions is in mozilla/network/main/mktrace.c. All the logging stuff is based on top of NSPR's log facility.

So how will this all get used? We're working on building a database that includes session, document, and event information. More on this soon...