gecko-dev

mirror of https://github.com/mozilla/gecko-dev.git synced 2024-11-05 08:35:26 +00:00

History

Jerry.Kirk%Nexwarecorp.com e4d2d945fd Updating for the Neutrino Platform. Not finished yet, still looking for the "pcs" memmber in the malloc_log_entry structure.		2000-02-09 14:25:18 +00:00
..
stub	Updating for the Neutrino Platform. Not finished yet, still looking	2000-02-09 14:25:18 +00:00
.cvsignore
bfd.cpp
coff.cpp
config.h
elf.cpp
intcnt.cpp
intcnt.h
jprof.h
leaky.cpp
leaky.h
libmalloc.cpp	Updating for the Neutrino Platform. Not finished yet, still looking	2000-02-09 14:25:18 +00:00
libmalloc.h
Makefile.in	Fix the jprof makefile so that the libs are actually installed in the libs phase (like they are in makefiles that use rules.mk). Therefore, compiling a fresh or clobber build after building jprof will no longer fail when building the mozilla executable.	2000-02-03 00:29:26 +00:00
README.html	Update the jprof documentation.	2000-02-03 14:42:27 +00:00
strset.cpp
strset.h

README.html

<html>
<head><title>The Jprof Profiler</title></head><body>
<center><h1>The Jprof Profiler</h1></center><hr>

<h2>Introduction</h2>

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.

<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>
<P>
Next, enable jprof and rebuild mozilla:
<P>
<pre>
configure --enable-jprof
make
</pre>
Now you can run jprof.  To do this the JPROF_FLAGS environment variable
must be set.  As a simple example:
<pre>
cd dist/bin
env JPROF_FLAGS=JP_START LD_LIBRARY_PATH=. ./mozilla-bin
</pre>
<P>
The JPROF_FLAGS environment variable can be composed of several substrings
which have the following meanings:
<ul>
    <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).
    <li> JP_FIRST=x : Wait x seconds before starting the timer
    <li> JP_PERIOD=y : Set timer to interrupt every y seconds
    <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.
</ul>

For example you could say:

<pre>
setenv JPROF_FLAGS "JP_START JP_FIRST=3 JP_PERIOD=0.025"
</pre>

<P>
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
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:

<pre>
./jprof mozilla-bin ./jprof-log > tmp.html
</pre>

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.
<P>
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.
<P>
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.
<P>
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>
Currently jprof has only been tested under Red Hat Linux 6.1.  It is known
to not work under Red Hat Linux 6.0.  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.