2000-01-18 06:43:26 +03:00
|
|
|
<html>
|
|
|
|
|
<head><title>The Jprof Profiler</title></head><body>
|
2000-02-03 17:42:27 +03:00
|
|
|
<center><h1>The Jprof Profiler</h1></center><hr>
|
2000-01-25 05:46:30 +03:00
|
|
|
|
2000-01-18 06:43:26 +03:00
|
|
|
<h2>Introduction</h2>
|
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
|
|
|
|
|
|
|
|
<P> <h2>Operation</h2>
|
|
|
|
|
|
|
|
|
|
Jprof operates by installing a timer which periodically interrupts mozilla.
|
|
|
|
|
When this timer goes off, the jprof code inside mozilla walks the function
|
|
|
|
|
call stack to determine which code was executing. By collecting a large
|
|
|
|
|
number of these call stacks, it is possible to deduce where mozilla is
|
|
|
|
|
spending its time.
|
|
|
|
|
|
|
|
|
|
<P> <h2>Use</h2>
|
|
|
|
|
|
|
|
|
|
First, check out the jprof source code since it is not a part of the
|
|
|
|
|
default SeaMonkeyAll CVS tag. To do this do:
|
|
|
|
|
<pre>
|
|
|
|
|
cvs co mozilla/tools/jprof
|
|
|
|
|
<pre>
|
2000-01-18 06:43:26 +03:00
|
|
|
<P>
|
2000-01-25 05:46:30 +03:00
|
|
|
Next, enable jprof and rebuild mozilla:
|
2000-01-18 06:43:26 +03:00
|
|
|
<P>
|
|
|
|
|
<pre>
|
2000-01-25 05:46:30 +03:00
|
|
|
configure --enable-jprof
|
|
|
|
|
make
|
2000-01-18 06:43:26 +03:00
|
|
|
</pre>
|
2000-01-25 05:46:30 +03:00
|
|
|
Now you can run jprof. To do this the JPROF_FLAGS environment variable
|
|
|
|
|
must be set. As a simple example:
|
2000-01-18 06:43:26 +03:00
|
|
|
<pre>
|
2000-01-25 05:46:30 +03:00
|
|
|
cd dist/bin
|
2000-01-18 06:43:26 +03:00
|
|
|
env JPROF_FLAGS=JP_START LD_LIBRARY_PATH=. ./mozilla-bin
|
|
|
|
|
</pre>
|
2000-01-25 05:46:30 +03:00
|
|
|
<P>
|
|
|
|
|
The JPROF_FLAGS environment variable can be composed of several substrings
|
|
|
|
|
which have the following meanings:
|
|
|
|
|
<ul>
|
2000-02-03 17:42:27 +03:00
|
|
|
<li> JP_START : Install the signal handler, and start sending the
|
|
|
|
|
timer signals.
|
|
|
|
|
<li> JP_DEFER : Install the signal handler, but don't start sending
|
|
|
|
|
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 JP_REALTIME is used).
|
2000-01-25 05:46:30 +03:00
|
|
|
<li> JP_FIRST=x : Wait x seconds before starting the timer
|
2000-01-29 23:39:48 +03:00
|
|
|
<li> JP_PERIOD=y : Set timer to interrupt every y seconds
|
2000-02-03 17:42:27 +03:00
|
|
|
<li> JP_REALTIME : Do the profiling in intervals of real time rather
|
|
|
|
|
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.
|
2000-01-25 05:46:30 +03:00
|
|
|
</ul>
|
|
|
|
|
|
|
|
|
|
For example you could say:
|
2000-01-18 06:43:26 +03:00
|
|
|
|
|
|
|
|
<pre>
|
2000-01-29 23:39:48 +03:00
|
|
|
setenv JPROF_FLAGS "JP_START JP_FIRST=3 JP_PERIOD=0.025"
|
2000-01-18 06:43:26 +03:00
|
|
|
</pre>
|
2000-01-25 05:46:30 +03:00
|
|
|
|
|
|
|
|
<P>
|
2000-02-03 17:42:27 +03:00
|
|
|
When mozilla runs with jprof enabled, it writes to a file called jprof-log
|
|
|
|
|
for each timer signal and it writes to jprof-map when it exits.
|
|
|
|
|
Sending a SIGUSR1 to mozilla (<code>kill -USR1</code>) 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.
|
|
|
|
|
(After a SIGUSR1, sending another timer signal (SIGPROF or SIGALRM)
|
|
|
|
|
could be used to continue writing data to the same output, although this
|
|
|
|
|
has not been tested.)
|
|
|
|
|
|
|
|
|
|
<p>
|
|
|
|
|
The jprof executable is used to turn these
|
2000-01-25 05:46:30 +03:00
|
|
|
files 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>
|
2000-01-25 05:46:30 +03:00
|
|
|
./jprof mozilla-bin ./jprof-log > tmp.html
|
2000-01-18 06:43:26 +03:00
|
|
|
</pre>
|
|
|
|
|
|
2000-01-25 05:46:30 +03:00
|
|
|
This will generate the file tmp.html which you should view in a web browser.
|
|
|
|
|
|
|
|
|
|
<P> <h2>Interpretation</h2>
|
|
|
|
|
|
|
|
|
|
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.
|
|
|
|
|
|
|
|
|
|
<P> <h3>Flat output</h3>
|
|
|
|
|
|
|
|
|
|
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>
|
|
|
|
|
Count Function Name
|
|
|
|
|
36 <A href="#175458">_init</a>
|
|
|
|
|
30 <A href="#186088">SelectorMatches(nsIPresContext *, nsCSSSelector *, nsIContent *, int)</a>
|
|
|
|
|
22 <A href="#101380">_init</a>
|
|
|
|
|
22 <A href="#1991">_dl_lookup_symbol</a>
|
|
|
|
|
</pre> </blockquote>
|
|
|
|
|
|
|
|
|
|
In general, the functions with the highest count are the functions which
|
|
|
|
|
are taking the most time.
|
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.
|
|
|
|
|
|
|
|
|
|
<P> <h3>Hierarchical output</h3>
|
|
|
|
|
|
|
|
|
|
The hierarchical output is divided up into sections, with each section
|
|
|
|
|
corresponding to one function. A typical section looks something like
|
|
|
|
|
this:
|
|
|
|
|
|
|
|
|
|
<blockquote><pre>
|
|
|
|
|
639 <A href="#76801">nsWidget::OnMotionNotifySignal(_GdkEventMotion *)</A>
|
|
|
|
|
11 <A href="#76810">nsWidget::OnButtonReleaseSignal(_GdkEventButton *)</A>
|
|
|
|
|
2 <A href="#76809">nsWidget::OnButtonPressSignal(_GdkEventButton *)</A>
|
|
|
|
|
76787 0 652 <A name=76787>nsWidget::DispatchMouseEvent(nsMouseEvent &)</a>
|
|
|
|
|
652 <A href="#76779">nsWidget::DispatchWindowEvent(nsGUIEvent *)</A>
|
|
|
|
|
</pre></blockquote>
|
|
|
|
|
|
|
|
|
|
This block corresponds to the function nsWidget::DispatchMouseEvent.
|
|
|
|
|
You can determine this because it is preceded by three numbers while
|
|
|
|
|
the other function names are preceded by only one number. These three
|
|
|
|
|
numbers have the following meaning. The number on the left (76787)
|
|
|
|
|
is the index number, and is not important. The center number (0)
|
|
|
|
|
is the number of times this function was interrupted by the timer.
|
|
|
|
|
The last number (652) is the number of times this function was in the
|
|
|
|
|
call stack when the timer went off. For our example we can see that
|
|
|
|
|
our function was in the call stack for 652 interrupt ticks, but we were
|
|
|
|
|
never the function that was running when the interrupt arrived.
|
2000-01-18 06:43:26 +03:00
|
|
|
<P>
|
2000-01-25 05:46:30 +03:00
|
|
|
The functions listed above the line for nsWidget::DispatchMouseEvent, are
|
|
|
|
|
the functions which are calling this function. The numbers to the left of
|
|
|
|
|
these function names are the number of times these functions were in the
|
|
|
|
|
call stack as callers of nsWidget::DispatchMouseEvent. In our example,
|
|
|
|
|
we were called 11 times by the function nsWidget::OnButtonReleaseSignal.
|
2000-01-18 06:43:26 +03:00
|
|
|
<P>
|
2000-01-25 05:46:30 +03:00
|
|
|
The functions listed below the list for nsWidget::DispatchMouseEvent,
|
|
|
|
|
are the functions this function was calling when the timer went off.
|
|
|
|
|
The numbers to the left of the function names are the number of times
|
|
|
|
|
it was in the call stack as a callee of our function when the timer
|
|
|
|
|
went off. In our example, each of the 652 times the timer went off
|
|
|
|
|
and nsWidget::DispatchMouseEvent was in the call stack it was calling
|
|
|
|
|
nsWidget::DispatchWindowEvent.
|
|
|
|
|
|
|
|
|
|
<P> <h2>Bugs</h2>
|
2000-05-29 23:31:29 +04:00
|
|
|
Jprof has only been tested under Red Hat Linux 6.0, 6.1, and 6.2. It does
|
|
|
|
|
not work under 6.0, though it is possible hack up the source code and make
|
|
|
|
|
it work there. The way I determine the stack trace from inside the
|
|
|
|
|
signal handler is tightly bound to the version of glibc that is running.
|
|
|
|
|
If you know of a more portable way to get this information please let
|
|
|
|
|
me know.
|
2000-02-23 05:51:39 +03:00
|
|
|
<P> <h3>Update</h3>
|
|
|
|
|
Ben Bucksch reports that installing the Red Hat 6.1 glibc rpms on a Red Hat
|
|
|
|
|
6.0 system allows jprof to work, and does not seem to break anything except
|
|
|
|
|
gdm (the Gnome login program), and that can be fixed by installing the RH 6.1
|
|
|
|
|
gdb rpm.
|
2000-03-14 06:50:43 +03:00
|
|
|
<h3>Update</h3>
|
|
|
|
|
David Baron reports that jprof works under RedHat 6.0 if one uncomments
|
|
|
|
|
the <code>#define JPROF_PTHREAD_HACK</code> near the beginning of
|
|
|
|
|
<code>libmalloc.cpp</code>.
|
