michael@0: michael@0: michael@0: michael@0: The Jprof Profiler michael@0: michael@0: michael@0: michael@0:

The Jprof Profiler

michael@0: michael@0: jim_nance@yahoo.com

michael@0: Recent (4/2011) updates Randell Jesup (see bugzilla for contact info) michael@0: michael@0:

michael@0: michael@0: Introduction | Operation | michael@0: Setup | Usage | michael@0: Interpretation michael@0: michael@0: michael@0:

michael@0: michael@0:

Introduction

michael@0: michael@0: Jprof is a profiling tool. I am writing it because I need to find out michael@0: where mozilla is spending its time, and there do not seem to be any michael@0: profilers for Linux that can handle threads and/or shared libraries. michael@0: This code is based heavily on Kipp Hickman's leaky. michael@0: michael@0:

Operation

michael@0: michael@0: Jprof operates by installing a timer which periodically interrupts mozilla. michael@0: When this timer goes off, the jprof code inside mozilla walks the function call michael@0: stack to determine which code was executing and saves the results into the michael@0: jprof-log and jprof-map files. By collecting a large michael@0: number of these call stacks, it is possible to deduce where mozilla is spending michael@0: its time. michael@0: michael@0:

Setup

michael@0: michael@0:

Configure your mozilla with jprof support by adding michael@0: --enable-jprof to your configure options (eg adding michael@0: ac_add_options --enable-jprof to your .mozconfig) and michael@0: making sure that you do not have the michael@0: --enable-strip configure option set -- jprof needs symbols to michael@0: operate. On many architectures with GCC, you'll need to add michael@0: --enable-optimize="-O3 -fno-omit-frame-pointer" or the michael@0: equivalent to ensure frame pointer generation in the compiler you're using.

michael@0: michael@0:

Finally, build mozilla with your new configuration. Now you can run jprof.

michael@0: michael@0:

Usage

michael@0:

 jprof [-v] [-t] [-e exclude] [-i include] [-s stackdepth] [--last] [--all] [--start n [--end m]] [--output-dir dir] prog log [log2 ...]

michael@0: Options: michael@0:

-s depth : Limit depth looked at from captured stack michael@0: frames
-v : Output some information about the symbols, memory map, etc.
-t or --threads : Group output according to thread. May require external michael@0: LD_PRELOAD library to help force sampling of spawned threads; jprof michael@0: may capture the main thread only. See gprof-helper; michael@0: it may need adaption for jprof.
--only-thread id : Only output data for thread 'id'
-e exclusion : Allows excluding specific stack frames
-i inclusion : Allows including specific stack frames
--last : Only process data from the last 'section' of sampling michael@0: (starting at the last PROF)
--start N : Start processing data at 'section' N
--end N : Stop processing data at 'section' N
--output-dir dir : Store generated .html files in the given directory

michael@0: The behavior of jprof is determined by the value of the JPROF_FLAGS environment michael@0: variable. This environment variable can be composed of several substrings michael@0: which have the following meanings: michael@0:

JP_START : Install the signal handler, and start sending the michael@0: timer signals. michael@0: michael@0:
JP_DEFER : Install the signal handler, but don't start sending michael@0: the timer signals. The user must start the signals by sending the first michael@0: one (with kill -PROF, or with kill -ALRM if michael@0: JP_REALTIME is used, or with kill -POLL (also known as kill -IO) if JP_RTC_HZ is used). michael@0: michael@0:
JP_FIRST=x : Wait x seconds before starting the timer michael@0: michael@0:
JP_PERIOD=y : Set timer to interrupt every y seconds. Only michael@0: values of y greater than or equal to 0.001 are supported. Default is michael@0: 0.050 (50ms). michael@0: michael@0:
JP_REALTIME : Do the profiling in intervals of real time rather michael@0: than intervals of time used by the mozilla process (and the kernel michael@0: when doing work for mozilla). This could probably lead to weird michael@0: results (you'll see whatever runs when mozilla is waiting for events), michael@0: but is needed to see time spent in the X server. michael@0: michael@0:
JP_RTC_HZ=freq : This option, only available on Linux if the michael@0: kernel is built with RTC support, makes jprof use the RTC timer instead of michael@0: using its own timer. This option, like JP_REALTIME, uses intervals of real michael@0: time. This option overrides JP_PERIOD. freq is the frequency michael@0: at which the timer should fire, measured in Hz. It must be a power of 2. michael@0: The maximal frequency allowed by the kernel can be changed by writing to michael@0: /proc/sys/dev/rtc/max-user-freq; the maximum value it can be michael@0: set to is 8192. Note that /dev/rtc will need to be readable michael@0: by the Firefox process; making that file world-readable is a simple way to michael@0: accomplish that. michael@0: michael@0:
JP_CIRCULAR=size : This tells jprof to store samples in a michael@0: circular buffer of the given size, which then will be saved (appended) michael@0: to disk when SIGUSR1 is received or JProfStopProfiling is done. If the michael@0: buffer overflows, the oldest entries will be evicted until there's michael@0: space for the new entry.
michael@0: michael@0: SIGUSR2 will cause the circular buffer to be cleared. michael@0: michael@0:
JP_FILENAME=basefilename : This is the filename used for michael@0: saving the log files to; the default is "jprof-log". If Electrolysis michael@0: is used, each process after the first will have the process ID michael@0: added ("jprof-log-3212"); michael@0: michael@0:

michael@0: michael@0:

Starting and stopping jprof from JavaScript

michael@0:

michael@0: A build with jprof enabled adds four functions to the Window object:

michael@0: JProfStartProfiling() and JProfStopProfiling(): When used with JP_DEFER, these michael@0: allow one to start and stop the timer just around whatever critical section is michael@0: being profiled.

michael@0: JProfClearCircular() and JProfSaveCircular(): michael@0: These clear the circular buffer and save the buffer (without stopping), respectively.

michael@0: michael@0:

Examples of JPROF_FLAGS usage

michael@0:

To make the timer start firing 3 seconds after the program is started and michael@0: fire every 25 milliseconds of program time use: michael@0:
```
michael@0:         setenv JPROF_FLAGS "JP_START JP_FIRST=3 JP_PERIOD=0.025" 
```
michael@0: michael@0:
To make the timer start on your signal and fire every 1 millisecond of michael@0: program time use: michael@0:
```
michael@0:         setenv JPROF_FLAGS "JP_DEFER JP_PERIOD=0.001" 
```
michael@0: michael@0:
To make the timer start on your signal and fire every 10 milliseconds of michael@0: wall-clock time use: michael@0:
```
michael@0:         setenv JPROF_FLAGS "JP_DEFER JP_PERIOD=0.010 JP_REALTIME" 
```
michael@0: michael@0:
To make the timer start on your signal and fire at 8192 Hz in wall-clock michael@0: time use: michael@0:
```
michael@0:         setenv JPROF_FLAGS "JP_DEFER JP_RTC_HZ=8192" 
```
michael@0: michael@0:
To make the timer start on JProfStartProfiling() and run continously michael@0: with a 1ms sample rate until told to stop, then save the last 1MB of michael@0: data: michael@0:
```
michael@0:         setenv JPROF_FLAGS "JP_DEFER JP_CIRCULAR=1048576 JP_PERIOD=0.001" 
```
michael@0: michael@0:

michael@0: michael@0:

Pausing profiles

michael@0: michael@0:

jprof can be paused at any time by sending a SIGUSR1 to mozilla (kill michael@0: -USR1). This will cause the timer signals to stop and jprof-map to be michael@0: written, but it will not close jprof-log. Combining SIGUSR1 with the JP_DEFER michael@0: option allows profiling of one sequence of actions by starting the timer right michael@0: before starting the actions and stopping the timer right afterward. michael@0: michael@0:

After a SIGUSR1, sending another timer signal (SIGPROF, SIGALRM, or SIGPOLL (aka SIGIO), michael@0: depending on the mode) can be used to continue writing data to the same michael@0: output. michael@0: michael@0:

SIGUSR2 will cause the circular buffer to be cleared, if it's in use. michael@0: This is useful right before running a test when you're using a large, michael@0: continuous circular buffer, or programmatically at the start of an action michael@0: which might take too long (JProfClearCircular()). michael@0: michael@0:

Looking at the results

michael@0: michael@0: Now that we have jprof-log and jprof-map files, we michael@0: can use the jprof executable is used to turn them into readable output. To do michael@0: this jprof needs the name of the mozilla binary and the log file. It deduces michael@0: the name of the map file: michael@0: michael@0:

michael@0:   ./jprof /home/user/mozilla/objdir/dist/bin/firefox ./jprof-log > tmp.html
michael@0:

michael@0: michael@0: This will generate the file tmp.html which you should view in a michael@0: web browser. michael@0: michael@0:

michael@0:   ./jprof --output-dir=/tmp /home/user/mozilla/objdir/dist/bin/firefox ./jprof-log*
michael@0:

michael@0: michael@0: This will generate a set of files in /tmp for each process. michael@0: michael@0: michael@0:

Interpretation

michael@0: michael@0: michael@0: The Jprof output is split into a flat portion and a hierarchical portion. michael@0: There are links to each section at the top of the page. It is typically michael@0: easier to analyze the profile by starting with the flat output and following michael@0: the links contained in the flat output up to the hierarchical output. michael@0: michael@0:

Flat output

michael@0: michael@0: The flat portion of the profile indicates which functions were executing michael@0: when the timer was going off. It is displayed as a list of functions names michael@0: on the right and the number of times that function was interrupted on the michael@0: left. The list is sorted by decreasing interrupt count. For example: michael@0: michael@0:

michael@0: Total hit count: 151603
michael@0: Count %Total  Function Name
michael@0: 
michael@0: 8806   5.8     __libc_poll
michael@0: 2254   1.5     __i686.get_pc_thunk.bx
michael@0: 2053   1.4     _int_malloc
michael@0: 1777   1.2     nsStyleContext::GetStyleData(nsStyleStructID)
michael@0: 1600   1.1     __libc_malloc
michael@0: 1552   1.0     nsCOMPtr_base::~nsCOMPtr_base()
michael@0:

michael@0: michael@0: This shows that of the 151603 times the timer fired, 1777 (1.2% of the total) were inside nsStyleContext::GetStyleData() and 1552 (1.0% of the total) were in the nsCOMPtr_base destructor. michael@0: michael@0:

michael@0: In general, the functions with the highest count are the functions which michael@0: are taking the most time. michael@0: michael@0:

michael@0: The function names are linked to the entry for that function in the michael@0: hierarchical profile, which is described in the next section. michael@0: michael@0:

Hierarchical output

michael@0: michael@0: The hierarchical output is divided up into sections, with each section michael@0: corresponding to one function. A typical section looks something like michael@0: this: michael@0: michael@0:

michael@0:  index  Count         Hits      Function Name
michael@0:                            545 (46.4%) nsBlockFrame::ReflowInlineFrames(nsBlockReflowState&, nsLineList_iterator, int*)
michael@0:                            100 (8.5%)  nsBlockFrame::ReflowDirtyLines(nsBlockReflowState&)
michael@0:  72870      4 (0.3%)       645 (54.9%) nsBlockFrame::DoReflowInlineFrames(nsBlockReflowState&, nsLineLayout&, nsLineList_iterator, nsFlowAreaRect&, int&, nsFloatManager::SavedState*, int*, LineReflowStatus*, int)
michael@0:                            545 (46.4%) nsBlockFrame::ReflowInlineFrame(nsBlockReflowState&, nsLineLayout&, nsLineList_iterator, nsIFrame*, LineReflowStatus*)
michael@0:                             83 (7.1%)  nsBlockFrame::PlaceLine(nsBlockReflowState&, nsLineLayout&, nsLineList_iterator, nsFloatManager::SavedState*, nsRect&, int&, int*)
michael@0:                              9 (0.8%)  nsLineLayout::BeginLineReflow(int, int, int, int, int, int)
michael@0:                              1 (0.1%)  nsTextFrame::GetType() const
michael@0:                              1 (0.1%)  nsLineLayout::RelativePositionFrames(nsOverflowAreas&)
michael@0:                              1 (0.1%)  __i686.get_pc_thunk.bx
michael@0:                              1 (0.1%)  PL_ArenaAllocate
michael@0:

michael@0: michael@0: The information this block tells us is: michael@0: michael@0:

There were 4 profiler hits in nsBlockFrame::DoReflowInlineFrames michael@0:
There were 645 profiler hits in or under nsBlockFrame::DoReflowInlineFrames. Of these: michael@0:
- 545 were in or under nsBlockFrame::ReflowInlineFrame michael@0:
- 83 were in or under nsBlockFrame::PlaceLine michael@0:
- 9 were in or under nsLineLayout::BeginLineReflow michael@0:
- 1 was in or under nsTextFrame::GetType michael@0:
- 1 was in or under nsLineLayout::RelativePositionFrames michael@0:
- 1 was in or under __i686.get_pc_thunk.bx michael@0:
- 1 was in or under PL_ArenaAllocate michael@0:
michael@0:
Of these 645 calls into nsBlockFrame::DoReflowInlineFrames: michael@0:
- 545 came from nsBlockFrame::ReflowInlineFrames michael@0:
- 100 came from nsBlockFrame::ReflowDirtyLines michael@0:
michael@0:

michael@0: michael@0: michael@0: The rest of this section explains how to read this information off from the jprof output. michael@0: michael@0:

This block corresponds to the function nsBlockFrame::DoReflowInlineFrames, which is michael@0: therefore bolded and not a link. The name of this function is preceded by michael@0: five numbers which have the following meaning. The number on the left (72870) michael@0: is the index number, and is not important. The next number (4) and the michael@0: percentage following (0.3%) are the number michael@0: of times this function was interrupted by the timer and the percentage of michael@0: the total hits that is. The last number pair ("645 (54.9%)") michael@0: are the number of times this function was in the call stack when the timer went michael@0: off. That is, the timer went off while we were in code that was ultimately michael@0: called from nsBlockFrame::DoReflowInlineFrames. michael@0:

For our example we can see that our function was in the call stack for michael@0: 645 interrupt ticks, but we were only the function that was running when michael@0: the interrupt arrived 4 times. michael@0:

michael@0: The functions listed above the line for nsBlockFrame::DoReflowInlineFrames are its michael@0: callers. The numbers to the left of these function names are the numbers of michael@0: times these functions were in the call stack as callers of michael@0: nsBlockFrame::DoReflowInlineFrames. In our example, we were called 545 times by michael@0: nsBlockFrame::ReflowInlineFrames and 100 times by michael@0: nsBlockFrame::ReflowDirtyLines. michael@0:

michael@0: The functions listed below the line for nsBlockFrame::DoReflowInlineFrames are its michael@0: callees. The numbers to the left of the function names are the numbers of michael@0: times these functions were in the callstack as callees of michael@0: nsBlockFrame::DoReflowInlineFrames and the corresponding percentages. In our example, of the 645 profiler hits under nsBlockFrame::DoReflowInlineFrames 545 were under nsBlockFrame::ReflowInlineFrame, 83 were under nsBlockFrame::PlaceLine, and so forth.

michael@0: michael@0: NOTE: If there are loops of execution or recursion, the numbers will michael@0: not add up and percentages can exceed 100%. If a function directly calls michael@0: itself "(self)" will be appended to the line, but indirect recursion will michael@0: not be marked. michael@0: michael@0:

Bugs

michael@0: The current build of Jprof has only been tested under Ubuntu 8.04 LTS, but michael@0: should work under any fairly modern linux distribution using GCC/GLIBC. michael@0: Please update this document with any known compatibilities/incompatibilities. michael@0:

michael@0: If you get an error:

Inconsistency detected by ld.so: dl-open.c: 260: dl_open_worker: Assertion `_dl_debug_initialize (0, args->nsid)->r_state == RT_CONSISTENT' failed! michael@0:

that means you've hit a timing hole in the version of glibc you're michael@0: running. See Redhat bug 4578. michael@0: michael@0: michael@0: michael@0: