2000-01-18 06:43:26 +03:00
< html >
2001-02-16 01:22:52 +03:00
< head > < title > The Jprof Profiler< / title > < / head >
2000-01-25 05:46:30 +03:00
2001-02-16 01:22:52 +03:00
< body bgcolor = "#FFFFFF" text = "#000000"
link="#0000EE" vlink="#551A8B" alink="#FF0000">
< center >
< h1 > The Jprof Profiler< / h1 >
< font size = "-1" >
2011-05-15 13:47:48 +04:00
< a href = "mailto:jim_nance%yahoo.com" > jim_nance@yahoo.com< / a > < p >
Recent (4/2011) updates Randell Jesup (see bugzilla for contact info)
2001-02-16 01:22:52 +03:00
< / font >
2004-03-07 04:15:26 +03:00
< hr >
< a href = "#introduction" > Introduction< / a > | < a href = "#operation" > Operation< / a > |
< a href = "#setup" > Setup< / a > | < a href = "#usage" > Usage< / a > |
< a href = "#interpretation" > Interpretation< / a >
2001-02-16 01:22:52 +03:00
< / center >
< hr >
2004-03-07 04:15:26 +03:00
< h3 > < a name = "introduction" > Introduction< / a > < / h3 >
2000-01-25 05:46:30 +03:00
2000-01-18 06:43:26 +03:00
Jprof is a profiling tool. I am writing it because I need to find out
where mozilla is spending its time, and there do not seem to be any
profilers for Linux that can handle threads and/or shared libraries.
This code is based heavily on Kipp Hickman's leaky.
2000-01-25 05:46:30 +03:00
2004-03-07 04:15:26 +03:00
< h3 > < a name = "operation" > Operation< / a > < / h3 >
2000-01-25 05:46:30 +03:00
Jprof operates by installing a timer which periodically interrupts mozilla.
2004-03-07 04:15:26 +03:00
When this timer goes off, the jprof code inside mozilla walks the function call
stack to determine which code was executing and saves the results into the
< code > jprof-log< / code > and < code > jprof-map< / code > files. By collecting a large
number of these call stacks, it is possible to deduce where mozilla is spending
its time.
2000-01-25 05:46:30 +03:00
2004-03-07 04:15:26 +03:00
< h3 > < a name = "setup" > Setup< / a > < / h3 >
2000-01-25 05:46:30 +03:00
2011-06-01 11:51:03 +04:00
< p > Configure your mozilla with jprof support by adding
2006-03-09 19:53:43 +03:00
< code > --enable-jprof< / code > to your configure options (eg adding
< code > ac_add_options --enable-jprof< / code > to your < code > .mozconfig< / code > ) and
making sure that you do < strong > not< / strong > have the
< code > --enable-strip< / code > configure option set -- jprof needs symbols to
2011-05-15 13:47:48 +04:00
operate. On many architectures with GCC, you'll need to add
< code > --enable-optimize="-O3 -fno-omit-frame-pointer"< / code > or the
equivalent to ensure frame pointer generation in the compiler you're using.< / p >
2006-03-09 19:53:43 +03:00
< p > Finally, build mozilla with your new configuration. Now you can run jprof.< / p >
2004-03-07 04:15:26 +03:00
< h3 > < a name = "usage" > Usage< / a > < / h3 >
2011-08-12 19:59:20 +04:00
< pre > jprof [-v] [-t] [-e exclude] [-i include] [-s stackdepth] [--last] [--all] [--start n [--end m]] [--output-dir dir] prog log [log2 ...]< / pre >
2011-05-15 13:47:48 +04:00
Options:
< ul >
< li > < b > -s depth< / b > : Limit depth looked at from captured stack
frames< / li >
< li > < b > -v< / b > : Output some information about the symbols, memory map, etc.< / li >
2011-08-12 19:59:20 +04:00
< li > < b > -t or --threads< / b > : Group output according to thread. May require external
2011-05-15 13:47:48 +04:00
LD_PRELOAD library to help force sampling of spawned threads; jprof
2011-08-12 19:59:20 +04:00
may capture the main thread only. See < a
2011-05-15 13:47:48 +04:00
href="http://sam.zoy.org/writings/programming/gprof.html">gprof-helper< / a > ;
it may need adaption for jprof.< / li >
2011-08-12 19:59:20 +04:00
< li > < b > --only-thread id< / b > : Only output data for thread 'id'< / li >
2011-05-15 13:47:48 +04:00
< li > < b > -e exclusion< / b > : Allows excluding specific stack frames< / li >
< li > < b > -i inclusion< / b > : Allows including specific stack frames< / li >
2011-08-12 19:59:20 +04:00
< li > < b > --last< / b > : Only process data from the last 'section' of sampling
(starting at the last PROF)< / li >
< li > < b > --start N< / b > : Start processing data at 'section' N < / li >
< li > < b > --end N< / b > : Stop processing data at 'section' N < / li >
< li > < b > --output-dir dir< / b > : Store generated .html files in the given directory < / li >
2011-05-15 13:47:48 +04:00
< / ul >
2004-03-07 04:15:26 +03:00
The behavior of jprof is determined by the value of the JPROF_FLAGS environment
variable. This environment variable can be composed of several substrings
2000-01-25 05:46:30 +03:00
which have the following meanings:
< ul >
2001-02-16 01:22:52 +03:00
< li > < b > JP_START< / b > : Install the signal handler, and start sending the
2000-02-03 17:42:27 +03:00
timer signals.
2004-03-07 04:15:26 +03:00
2001-02-16 01:22:52 +03:00
< li > < b > JP_DEFER< / b > : Install the signal handler, but don't start sending
2004-03-07 04:15:26 +03:00
the timer signals. The user must start the signals by sending the first
one (with < code > kill -PROF< / code > , or with < code > kill -ALRM< / code > if
2004-04-24 22:00:40 +04:00
JP_REALTIME is used, or with < code > kill -POLL< / code > (also known as < code > kill -IO< / code > ) if JP_RTC_HZ is used).
2004-03-07 04:15:26 +03:00
2007-01-26 07:31:57 +03:00
< li > < b > JP_FIRST=x< / b > : Wait x seconds before starting the timer
2004-03-07 04:15:26 +03:00
< li > < b > JP_PERIOD=y< / b > : Set timer to interrupt every y seconds. Only
2011-05-15 13:47:48 +04:00
values of y greater than or equal to 0.001 are supported. Default is
0.050 (50ms).
2004-03-07 04:15:26 +03:00
2001-02-16 01:22:52 +03:00
< li > < b > JP_REALTIME< / b > : Do the profiling in intervals of real time rather
2000-02-03 17:42:27 +03:00
than intervals of time used by the mozilla process (and the kernel
when doing work for mozilla). This could probably lead to weird
results (you'll see whatever runs when mozilla is waiting for events),
but is needed to see time spent in the X server.
2004-03-07 04:15:26 +03:00
< li > < b > JP_RTC_HZ=freq< / b > : This option, only available on Linux if the
kernel is built with RTC support, makes jprof use the RTC timer instead of
using its own timer. This option, like JP_REALTIME, uses intervals of real
2006-03-09 19:53:43 +03:00
time. This option overrides JP_PERIOD. < code > freq< / code > is the frequency
at which the timer should fire, measured in Hz. It must be a power of 2.
The maximal frequency allowed by the kernel can be changed by writing to
2004-03-07 04:15:26 +03:00
< code > /proc/sys/dev/rtc/max-user-freq< / code > ; the maximum value it can be
2006-03-09 19:53:43 +03:00
set to is 8192. Note that < code > /dev/rtc< / code > will need to be readable
by the Firefox process; making that file world-readable is a simple way to
accomplish that.
2011-08-12 19:59:20 +04:00
< li > < b > JP_FILENAME=basefilename< / b > : This is the filename used for
saving the log files to; the default is "jprof-log". If Electrolysis
is used, each process after the first will have the process ID
added ("jprof-log-3212");
2000-01-25 05:46:30 +03:00
< / ul >
2007-12-06 20:04:56 +03:00
< h4 > Starting and stopping jprof from JavaScript< / h4 >
< p >
A build with jprof enabled adds two functions to the Window object:
< code > JProfStartProfiling()< / code > and < code > JProfStopProfiling()< / code > . When used with JP_DEFER, these
allow one to start and stop the timer just around whatever critical section is
being profiled
< / p >
2004-03-07 04:15:26 +03:00
< h4 > Examples of JPROF_FLAGS usage< / h4 >
< ul >
2000-01-18 06:43:26 +03:00
2004-03-07 04:15:26 +03:00
< li > To make the timer start firing 3 seconds after the program is started and
fire every 25 milliseconds of program time use:
< pre >
setenv JPROF_FLAGS "JP_START JP_FIRST=3 JP_PERIOD=0.025" < / pre >
2000-01-25 05:46:30 +03:00
2011-05-15 13:47:48 +04:00
< li > To make the timer start on your signal and fire every 1 millisecond of
2004-03-07 04:15:26 +03:00
program time use:
< pre >
2011-05-15 13:47:48 +04:00
setenv JPROF_FLAGS "JP_DEFER JP_PERIOD=0.001" < / pre >
2000-02-03 17:42:27 +03:00
2004-03-07 04:15:26 +03:00
< li > To make the timer start on your signal and fire every 10 milliseconds of
wall-clock time use:
< pre >
setenv JPROF_FLAGS "JP_DEFER JP_PERIOD=0.010 JP_REALTIME" < / pre >
< li > To make the timer start on your signal and fire at 8192 Hz in wall-clock
time use:
< pre >
2004-04-24 22:00:40 +04:00
setenv JPROF_FLAGS "JP_DEFER JP_RTC_HZ=8192" < / pre >
2004-03-07 04:15:26 +03:00
< / ul >
< h4 > Pausing profiles< / h4 >
< P > jprof can be paused at any time by sending a SIGUSR1 to mozilla (< code > kill
-USR1< / code > ). This will cause the timer signals to stop and jprof-map to be
written, but it will not close jprof-log. Combining SIGUSR1 with the JP_DEFER
option allows profiling of one sequence of actions by starting the timer right
before starting the actions and stopping the timer right afterward.
2004-04-24 22:00:40 +04:00
< P > After a SIGUSR1, sending another timer signal (SIGPROF, SIGALRM, or SIGPOLL (aka SIGIO),
2004-03-07 04:15:26 +03:00
depending on the mode) can be used to continue writing data to the same output.
< h4 > Looking at the results< / h4 >
Now that we have < code > jprof-log< / code > and < code > jprof-map< / code > files, we
can use the jprof executable is used to turn them into readable output. To do
this jprof needs the name of the mozilla binary and the log file. It deduces
the name of the map file:
2000-01-18 06:43:26 +03:00
< pre >
2011-08-12 19:59:20 +04:00
./jprof /home/user/mozilla/objdir/dist/bin/firefox ./jprof-log > tmp.html
2000-01-18 06:43:26 +03:00
< / pre >
2004-03-07 04:15:26 +03:00
This will generate the file < code > tmp.html< / code > which you should view in a
web browser.
2011-08-12 19:59:20 +04:00
< pre >
./jprof --output-dir=/tmp /home/user/mozilla/objdir/dist/bin/firefox ./jprof-log*
< / pre >
This will generate a set of files in /tmp for each process.
2004-03-07 04:15:26 +03:00
< h3 > < a name = "interpretation" > Interpretation< / a > < / h3 >
2000-01-25 05:46:30 +03:00
The Jprof output is split into a flat portion and a hierarchical portion.
There are links to each section at the top of the page. It is typically
easier to analyze the profile by starting with the flat output and following
the links contained in the flat output up to the hierarchical output.
2004-03-07 04:15:26 +03:00
< h4 > < a name = "flat" > Flat output< / a > < / h3 >
2000-01-25 05:46:30 +03:00
The flat portion of the profile indicates which functions were executing
when the timer was going off. It is displayed as a list of functions names
on the right and the number of times that function was interrupted on the
left. The list is sorted by decreasing interrupt count. For example:
< blockquote > < pre >
2004-03-07 04:15:26 +03:00
Total hit count: 151603
Count %Total Function Name
< a href = "#23081" > 8806 5.8 __libc_poll< / a >
< a href = "#40008" > 2254 1.5 __i686.get_pc_thunk.bx< / a >
< a href = "#21390" > 2053 1.4 _int_malloc< / a >
< a href = "#49013" > 1777 1.2 nsStyleContext::GetStyleData(nsStyleStructID)< / a >
< a href = "#21380" > 1600 1.1 __libc_malloc< / a >
< a href = "#603" > 1552 1.0 nsCOMPtr_base::~nsCOMPtr_base()< / a >
2000-01-25 05:46:30 +03:00
< / pre > < / blockquote >
2004-03-07 04:15:26 +03:00
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.
< p >
2000-01-25 05:46:30 +03:00
In general, the functions with the highest count are the functions which
are taking the most time.
2004-03-07 04:15:26 +03:00
2000-01-18 06:43:26 +03:00
< P >
2000-01-25 05:46:30 +03:00
The function names are linked to the entry for that function in the
hierarchical profile, which is described in the next section.
2004-03-07 04:15:26 +03:00
< h4 > < a name = "hier" > Hierarchical output< / a > < / h4 >
2000-01-25 05:46:30 +03:00
The hierarchical output is divided up into sections, with each section
corresponding to one function. A typical section looks something like
this:
< blockquote > < pre >
2011-05-15 13:47:48 +04:00
index Count Hits Function Name
< A href = "#72871" > 545 (46.4%) nsBlockFrame::ReflowInlineFrames(nsBlockReflowState& , nsLineList_iterator, int*)< / A >
< A href = "#72873" > 100 (8.5%) nsBlockFrame::ReflowDirtyLines(nsBlockReflowState& )< / A >
72870 4 (0.3%) < a name = 72870 > 645 (54.9%)< / a > < b > nsBlockFrame::DoReflowInlineFrames(nsBlockReflowState& , nsLineLayout& , nsLineList_iterator, nsFlowAreaRect& , int& , nsFloatManager::SavedState*, int*, LineReflowStatus*, int)< / b >
< A href = "#72821" > 545 (46.4%) nsBlockFrame::ReflowInlineFrame(nsBlockReflowState& , nsLineLayout& , nsLineList_iterator, nsIFrame*, LineReflowStatus*)< / A >
< A href = "#72853" > 83 (7.1%) nsBlockFrame::PlaceLine(nsBlockReflowState& , nsLineLayout& , nsLineList_iterator, nsFloatManager::SavedState*, nsRect& , int& , int*)< / A >
< A href = "#74150" > 9 (0.8%) nsLineLayout::BeginLineReflow(int, int, int, int, int, int)< / A >
< A href = "#74897" > 1 (0.1%) nsTextFrame::GetType() const< / A >
< A href = "#74131" > 1 (0.1%) nsLineLayout::RelativePositionFrames(nsOverflowAreas& )< / A >
< A href = "#58320" > 1 (0.1%) __i686.get_pc_thunk.bx< / A >
< A href = "#53077" > 1 (0.1%) PL_ArenaAllocate< / A >
2000-01-25 05:46:30 +03:00
< / pre > < / blockquote >
2004-03-07 04:15:26 +03:00
The information this block tells us is:
< ul >
2011-05-15 13:47:48 +04:00
< li > There were 4 profiler hits < em > in< / em > < code > nsBlockFrame::DoReflowInlineFrames< / code >
< li > There were 645 profiler hits < em > in or under< / em > < code > nsBlockFrame::DoReflowInlineFrames< / code > . Of these:
2004-03-07 04:15:26 +03:00
< ul >
2011-05-15 13:47:48 +04:00
< li > 545 were in or under < code > nsBlockFrame::ReflowInlineFrame< / code >
< li > 83 were in or under < code > nsBlockFrame::PlaceLine< / code >
< li > 9 were in or under < code > nsLineLayout::BeginLineReflow< / code >
< li > 1 was in or under < code > nsTextFrame::GetType< / code >
< li > 1 was in or under < code > nsLineLayout::RelativePositionFrames< / code >
< li > 1 was in or under < code > __i686.get_pc_thunk.bx< / code >
< li > 1 was in or under < code > PL_ArenaAllocate< / code >
2004-03-07 04:15:26 +03:00
< / ul >
2011-05-15 13:47:48 +04:00
< li > Of these 645 calls into < code > nsBlockFrame::DoReflowInlineFrames< / code > :
2004-03-07 04:15:26 +03:00
< ul >
2011-05-15 13:47:48 +04:00
< li > 545 came from < code > nsBlockFrame::ReflowInlineFrames< / code >
< li > 100 came from < code > nsBlockFrame::ReflowDirtyLines< / code >
2004-03-07 04:15:26 +03:00
< / ul >
< / ul >
The rest of this section explains how to read this information off from the jprof output.
2011-05-15 13:47:48 +04:00
< p > This block corresponds to the function < code > nsBlockFrame::DoReflowInlineFrames< / code > , which is
2004-03-07 04:15:26 +03:00
therefore bolded and not a link. The name of this function is preceded by
2011-05-15 13:47:48 +04:00
five numbers which have the following meaning. The number on the left (72870)
is the index number, and is not important. The next number (4) and the
percentage following (0.3%) are the number
of times this function was interrupted by the timer and the percentage of
the total hits that is. The last number pair ("645 (54.9%)")
are the number of times this function was in the call stack when the timer went
2004-03-07 04:15:26 +03:00
off. That is, the timer went off while we were in code that was ultimately
2011-05-15 13:47:48 +04:00
called from < code > nsBlockFrame::DoReflowInlineFrames< / code > .
2004-03-07 04:15:26 +03:00
< p > For our example we can see that our function was in the call stack for
2011-05-15 13:47:48 +04:00
645 interrupt ticks, but we were only the function that was running when
the interrupt arrived 4 times.
2000-01-18 06:43:26 +03:00
< P >
2011-05-15 13:47:48 +04:00
The functions listed above the line for < code > nsBlockFrame::DoReflowInlineFrames< / code > are its
2004-03-07 04:15:26 +03:00
callers. The numbers to the left of these function names are the numbers of
times these functions were in the call stack as callers of
2011-05-15 13:47:48 +04:00
< code > nsBlockFrame::DoReflowInlineFrames< / code > . In our example, we were called 545 times by
< code > nsBlockFrame::ReflowInlineFrames< / code > and 100 times by
< code > nsBlockFrame::ReflowDirtyLines< / code > .
2000-01-18 06:43:26 +03:00
< P >
2011-05-15 13:47:48 +04:00
The functions listed below the line for < code > nsBlockFrame::DoReflowInlineFrames< / code > are its
2004-03-07 04:15:26 +03:00
callees. The numbers to the left of the function names are the numbers of
2011-05-15 13:47:48 +04:00
times these functions were in the callstack as callees of
< code > nsBlockFrame::DoReflowInlineFrames< / code > and the corresponding percentages. In our example, of the 645 profiler hits under < code > nsBlockFrame::DoReflowInlineFrames< / code > 545 were under < code > nsBlockFrame::ReflowInlineFrame< / code > , 83 were under < code > nsBlockFrame::PlaceLine< / code > , and so forth.< p >
< b > NOTE:< / b > If there are loops of execution or recursion, the numbers will
not add up and percentages can exceed 100%. If a function directly calls
itself "(self)" will be appended to the line, but indirect recursion will
not be marked.
2000-01-25 05:46:30 +03:00
2001-02-16 01:22:52 +03:00
< h3 > Bugs< / h3 >
2011-05-15 13:47:48 +04:00
The current build of Jprof has only been tested under Ubuntu 8.04 LTS, but
should work under any fairly modern linux distribution using GCC/GLIBC.
Please update this document with any known compatibilities/incompatibilities.
< p >
If you get an error:< p > < code > Inconsistency detected by ld.so: dl-open.c: 260: dl_open_worker: Assertion `_dl_debug_initialize (0, args->nsid)->r_state == RT_CONSISTENT' failed!
< / code > < p > that means you've hit a timing hole in the version of glibc you're
running. See < a
href="http://sources.redhat.com/bugzilla/show_bug.cgi?id=4578">Redhat bug 4578< / a > .
<!-- <h3>Update</h3>
2001-02-16 01:22:52 +03:00
< ul >
< / ul >
2011-05-15 13:47:48 +04:00
-->
2001-02-16 01:22:52 +03:00
< / body >
< / html >
