path: root/ghc/docs/users_guide/profiling.vsgml

<sect>Profiling
<label id="profiling">
<p>
<nidx>profiling, with cost-centres</nidx>
<nidx>cost-centre profiling</nidx>

Glasgow Haskell comes with a time and space profiling system. Its
purpose is to help you improve your understanding of your program's
execution behaviour, so you can improve it.

Any comments, suggestions and/or improvements you have are welcome.
Recommended ``profiling tricks'' would be especially cool!

<sect1>How to profile a Haskell program
<label id="profiling-intro">
<p>

The GHC approach to profiling is very simple: annotate the expressions
you consider ``interesting'' with <em>cost centre</em> labels (strings);
so, for example, you might have:

<tscreen><verb>
f x y
  = let
	output1 = _scc_ "Pass1" ( pass1 x )
	output2 = _scc_ "Pass2" ( pass2 output1 y )
	output3 = _scc_ "Pass3" ( pass3 (output2 `zip` [1 .. ]) )
    in concat output3
</verb></tscreen>

The costs of the evaluating the expressions bound to @output1@,
@output2@ and @output3@ will be attributed to the ``cost
centres'' @Pass1@, @Pass2@ and @Pass3@, respectively.

The costs of evaluating other expressions, e.g., @concat output4@,
will be inherited by the scope which referenced the function @f@.

You can put in cost-centres via @_scc_@ constructs by hand, as in the
example above.  Perfectly cool.  That's probably what you
<em>would</em> do if your program divided into obvious ``passes'' or
``phases'', or whatever.

If your program is large or you have no clue what might be gobbling
all the time, you can get GHC to mark all functions with @_scc_@
constructs, automagically.  Add an @-auto@ compilation flag to the
usual @-prof@ option.

Once you start homing in on the Guilty Suspects, you may well switch
from automagically-inserted cost-centres to a few well-chosen ones of
your own.

To use profiling, you must <em>compile</em> and <em>run</em> with special
options.  (We usually forget the ``run'' magic!---Do as we say, not as
we do...) Details follow.

If you're serious about this profiling game, you should probably read
one or more of the Sansom/Peyton Jones papers about the GHC profiling
system.  Just visit the <url name="Glasgow FP group web page"
url="http://www.dcs.gla.ac.uk/fp/">...

<sect1>Compiling programs for profiling
<label id="prof-compiler-options">
<p>
<nidx>profiling options</nidx>
<nidx>options, for profiling</nidx>

To make use of the cost centre profiling system <em>all</em> modules must
be compiled and linked with the @-prof@ option.<nidx>-prof option</nidx>
Any @_scc_@ constructs you've put in your source will spring to life.

Without a @-prof@ option, your @_scc_@s are ignored; so you can
compiled @_scc_@-laden code without changing it.

There are a few other profiling-related compilation options.  Use them
<em>in addition to</em> @-prof@.  These do not have to be used
consistently for all modules in a program.

<descrip>
<tag>@-auto@:</tag>
<nidx>-auto option</nidx>
<nidx>cost centres, automatically inserting</nidx>
GHC will automatically add @_scc_@ constructs for
all top-level, exported functions.

<tag>@-auto-all@:</tag>
<nidx>-auto-all option</nidx>
<em>All</em> top-level functions, exported or not, will be automatically
@_scc_@'d.

<tag>@-caf-all@:</tag>
<nidx>-caf-all option</nidx>
The costs of all CAFs in a module are usually attributed to one
``big'' CAF cost-centre. With this option, all CAFs get their own cost-centre.
An ``if all else fails'' option...

%<tag>@-dict-all@:</tag>
%<nidx>-dict-all option</nidx>
%Similarly, this option means that all ``dictionaries'' (internal
%constructs to support Haskell overloading) should get their own
%cost-centre.  (Again, the costs are usually attributed to one ``big''
%DICT cost-centre.)
%
%Incidentally, something is probably Bad Wrong (i.e., a GHC bug) if you
%see big costs attributed to dictionaries.

<tag>@-ignore-scc@:</tag>
<nidx>-ignore-scc option</nidx>
Ignore any @_scc_@ constructs,
so a module which already has @_scc_@s can be
compiled for profiling with the annotations ignored.

<tag>@-G<group>@:</tag>
<nidx>-G&lt;group&gt; option</nidx>
Specifies the @<group>@ to be attached to all the cost-centres
declared in the module. If no group is specified it defaults to the
module name.
</descrip>

In addition to the @-prof@ option your system might be setup to enable
you to compile and link with the @-prof-details@ <nidx>-prof-details
option</nidx> option instead. This enables additional detailed counts
to be reported with the @-P@ RTS option.  

%-prof-details should also enable age profiling if we get it going again ...

<sect1>How to control your profiled program at runtime
<label id="prof-rts-options">
<p>
<nidx>profiling RTS options</nidx>
<nidx>RTS options, for profiling</nidx>

It isn't enough to compile your program for profiling with @-prof@!

When you <em>run</em> your profiled program, you must tell the runtime
system (RTS) what you want to profile (e.g., time and/or space), and
how you wish the collected data to be reported.  You also may wish to
set the sampling interval used in time profiling.

Executive summary: @./a.out +RTS -pT@ produces a time profile in
@a.out.prof@; @./a.out +RTS -hC@ produces space-profiling
info which can be mangled by @hp2ps@ and viewed with @ghostview@
(or equivalent).

Profiling runtime flags are passed to your program between the usual
@+RTS@ and @-RTS@ options.

<descrip>
<tag>@-p<sort>@ or @-P<sort>@:</tag>
<nidx>-p&lt;sort&gt; RTS option (profiling)</nidx>
<nidx>-P&lt;sort&gt; RTS option (profiling)</nidx>
<nidx>time profile</nidx>
<nidx>serial time profile</nidx>
The @-p?@ option produces a standard <em>time profile</em> report.
It is written into the file @<program>@@.prof@.

The @-P?@ option produces a more detailed report containing the
actual time and allocation data as well.  (Not used much.)

%The @-P?@ option also produces <em>serial time-profiling</em>
%information, in the file @<program>@@.time@. This can be
%converted into a (somewhat unsatisfactory) PostScript graph using
%@hp2ps@ (see Section <ref name="hp2ps - heap profile to PostScript" id="hp2ps">).

%???? -F2s needed for serial time profile??? ToDo

The @<sort>@ indicates how the cost centres are to be sorted in the
report. Valid @<sort>@ options are:
<descrip>
<tag>@T@:</tag> by time, largest first (the default);
<tag>@A@:</tag> by bytes allocated, largest first;
<tag>@C@:</tag> alphabetically by group, module and cost centre.
</descrip>

<tag>@-i<secs>@:</tag> <nidx>-i&lt;secs&gt; RTS option
(profiling)</nidx> Set the profiling (sampling) interval to @<secs>@
seconds (the default is 1~second).  Fractions are allowed: for example
@-i0.2@ will get 5 samples per second.

<tag>@-h<break-down>@:</tag>
<nidx>-h&lt;break-down&gt; RTS option (profiling)</nidx>
<nidx>heap profile</nidx>

Produce a detailed <em>space profile</em> of the heap occupied by live
closures. The profile is written to the file @<program>@@.hp@ from
which a PostScript graph can be produced using @hp2ps@ (see Section
<ref name="hp2ps - heap profile to PostScript" id="hp2ps">).

The heap space profile may be broken down by different criteria:
<descrip>
<tag>@-hC@:</tag> cost centre which produced the closure (the default).
<tag>@-hM@:</tag> cost centre module which produced the closure.
<tag>@-hG@:</tag> cost centre group which produced the closure.
<tag>@-hD@:</tag> closure description --- a string describing the closure.
<tag>@-hY@:</tag> closure type --- a string describing the closure's type.
%<tag>@-hT<ints>,<start>@:</tag> the time interval the closure was
%created. @<ints>@ specifies the no. of interval bands plotted
%(default 18) and @<start>@ the number of seconds after which the
%reported intervals start (default 0.0).
</descrip>
By default all live closures in the heap are profiled, but particular
closures of interest can be selected (see below). 
</descrip>


Heap (space) profiling uses hash tables. If these tables
should fill the run will abort. The
@-z<tbl><size>@<nidx>-z&lt;tbl&gt;&lt;size&gt; RTS option (profiling)</nidx> option is used to
increase the size of the relevant hash table (@C@, @M@,
@G@, @D@ or @Y@, defined as for @<break-down>@ above). The
actual size used is the next largest power of 2.

The heap profile can be restricted to particular closures of interest.
The closures of interest can selected by the attached cost centre
(module:label, module and group), closure category (description, type,
and kind) using the following options:

<descrip>
<tag>@-c{<mod>:<lab>,<mod>:<lab>...@}:</tag>
<nidx>-c{&lt;lab&gt;</nidx> RTS option (profiling)}
Selects individual cost centre(s).
<tag>@-m{<mod>,<mod>...@}:</tag>
<nidx>-m{&lt;mod&gt;</nidx> RTS option (profiling)}
Selects all cost centres from the module(s) specified.
<tag>@-g{<grp>,<grp>...@}:</tag>
<nidx>-g{&lt;grp&gt;</nidx> RTS option (profiling)}
Selects all cost centres from the groups(s) specified.
<tag>@-d{<des>,<des>...@}:</tag>
<nidx>-d{&lt;des&gt;</nidx> RTS option (profiling)}
Selects closures which have one of the specified descriptions.
<tag>@-y{<typ>,<typ>...@}:</tag>
<nidx>-y{&lt;typ&gt;</nidx> RTS option (profiling)}
Selects closures which have one of the specified type descriptions.
<tag>@-k{<knd>,<knd>...@}:</tag>
<nidx>-k{&lt;knd&gt;</nidx> RTS option (profiling)}
Selects closures which are of one of the specified closure kinds.
Valid closure kinds are @CON@ (constructor), @FN@ (manifest
function), @PAP@ (partial application), @BH@ (black hole) and
@THK@ (thunk).
</descrip>

The space occupied by a closure will be reported in the heap profile
if the closure satisfies the following logical expression:

<quote>
([-c] or [-m] or [-g]) and ([-d] or [-y] or [-k])
</quote>

where a particular option is true if the closure (or its attached cost
centre) is selected by the option (or the option is not specified).

<sect1>What's in a profiling report?
<label id="prof-output">
<p>
<nidx>profiling report, meaning thereof</nidx>

When you run your profiled program with the @-p@ RTS option <nidx>-p
RTS option</nidx>, you get the following information about your ``cost
centres'':

<descrip>
%-------------------------------------------------------------
<tag>@COST CENTRE@:</tag> The cost-centre's name.
%-------------------------------------------------------------
<tag>@MODULE@:</tag>
The module associated with the cost-centre;
important mostly if you have identically-named cost-centres in
different modules.
%-------------------------------------------------------------
<tag>@scc@:</tag>
How many times this cost-centre was entered; think
of it as ``I got to the @_scc_@ construct this many times...''
%-------------------------------------------------------------
<tag>@%time@:</tag>
What part of the time was spent in this cost-centre (see also ``ticks,''
below).
%-------------------------------------------------------------
<tag>@%alloc@:</tag>
What part of the memory allocation was done in this cost-centre
(see also ``bytes,'' below).
%-------------------------------------------------------------
<tag>@inner@:</tag>
How many times this cost-centre ``passed control'' to an inner
cost-centre; for example, @scc=4@ plus @subscc=8@ means
``This @_scc_@ was entered four times, but went out to
other @_scc_s@ eight times.''
%-------------------------------------------------------------
<tag>@cafs@:</tag>
<nidx>CAF, profiling</nidx>
How many CAFs this cost centre evaluated.
%-------------------------------------------------------------
<tag>@dicts@:</tag>
<nidx>Dictionaries, profiling</nidx>
How many dictionaries this cost centre evaluated.
</descrip>

In addition you can use the @-P@ RTS option <nidx></nidx> to get the following additional information: 
<descrip>
%-------------------------------------------------------------
<tag>@ticks@:</tag>  The raw number of time ``ticks'' which were
attributed to this cost-centre; from this, we get the @%time@
figure mentioned above.
%-------------------------------------------------------------
<tag>@bytes@:</tag> Number of bytes allocated in the heap while in
this cost-centre; again, this is the raw number from which we
get the @%alloc@ figure mentioned above.
</descrip>

Finally if you built your program with @-prof-details@
<nidx></nidx> the @-P@ RTS option will also
produce the following information:
<descrip>
%-------------------------------------------------------------
<tag>@closures@:</tag>
<nidx>closures, profiling</nidx>
How many heap objects were allocated; these objects may be of varying
size.  If you divide the number of bytes (mentioned below) by this
number of ``closures'', then you will get the average object size.
(Not too interesting, but still...)
%-------------------------------------------------------------
<tag>@thunks@:</tag>
<nidx>thunks, profiling</nidx>
How many times we entered (evaluated) a thunk---an unevaluated
object in the heap---while we were in this cost-centre.
%-------------------------------------------------------------
<tag>@funcs@:</tag>
<nidx>functions, profiling</nidx>
How many times we entered (evaluated) a function while we we in this
cost-centre.  (In Haskell, functions are first-class values and may be
passed as arguments, returned as results, evaluated, and generally
manipulated just like data values)
%-------------------------------------------------------------
<tag>@PAPs@:</tag>
<nidx>partial applications, profiling</nidx>
How many times we entered (evaluated) a partial application (PAP), i.e.,
a function applied to fewer arguments than it needs.  For example, @Int@
addition applied to one argument would be a PAP.  A PAP is really
just a particular form for a function.
</descrip>

<sect1>Producing graphical heap profiles
<label id="prof-graphs">
<p>
<nidx>heap profiles, producing</nidx>

Utility programs which produce graphical profiles.

<sect2>@hp2ps@--heap profile to PostScript
<label id="hp2ps">
<p>
<nidx>hp2ps (utility)</nidx>
<nidx>heap profiles</nidx>
<nidx>PostScript, from heap profiles</nidx>

Usage:

<tscreen> <verb>
hp2ps [flags] [<file>[.stat]]
</verb> </tscreen>

The program @hp2ps@<nidx>hp2ps program</nidx> converts a heap profile
as produced by the @-h<break-down>@<nidx>-h&lt;break-down&gt; RTS
option</nidx> runtime option into a PostScript graph of the heap
profile. By convention, the file to be processed by @hp2ps@ has a
@.hp@ extension. The PostScript output is written to @<file>@@.ps@. If
@<file>@ is omitted entirely, then the program behaves as a filter.

@hp2ps@ is distributed in @ghc/utils/hp2ps@ in a GHC source
distribution. It was originally developed by Dave Wakeling as part of
the HBC/LML heap profiler.

The flags are:
<descrip>
<tag>@-d@</tag>
In order to make graphs more readable, @hp2ps@ sorts the shaded
bands for each identifier. The default sort ordering is for the bands
with the largest area to be stacked on top of the smaller ones.  The
@-d@ option causes rougher bands (those representing series of
values with the largest standard deviations) to be stacked on top of
smoother ones.

<tag>@-b@</tag> 
Normally, @hp2ps@ puts the title of the graph in a small box at the
top of the page. However, if the JOB string is too long to fit in a
small box (more than 35 characters), then
@hp2ps@ will choose to use a big box instead.  The @-b@
option forces @hp2ps@ to use a big box.

<tag>@-e<float>[in|mm|pt]@</tag>
Generate encapsulated PostScript suitable for inclusion in LaTeX
documents.  Usually, the PostScript graph is drawn in landscape mode
in an area 9 inches wide by 6 inches high, and @hp2ps@ arranges
for this area to be approximately centred on a sheet of a4 paper.
This format is convenient of studying the graph in detail, but it is
unsuitable for inclusion in LaTeX documents.  The @-e@ option
causes the graph to be drawn in portrait mode, with float specifying
the width in inches, millimetres or points (the default).  The
resulting PostScript file conforms to the Encapsulated PostScript
(EPS) convention, and it can be included in a LaTeX document using
Rokicki's dvi-to-PostScript converter @dvips@.

<tag>@-g@</tag>
Create output suitable for the @gs@ PostScript previewer (or
similar). In this case the graph is printed in portrait mode without
scaling. The output is unsuitable for a laser printer.

<tag>@-l@</tag>
Normally a profile is limited to 20 bands with additional identifiers
being grouped into an @OTHER@ band. The @-l@ flag removes this
20 band and limit, producing as many bands as necessary. No key is
produced as it won't fit!. It is useful for creation time profiles
with many bands.

<tag>@-m<int>@</tag>
Normally a profile is limited to 20 bands with additional identifiers
being grouped into an @OTHER@ band. The @-m@ flag specifies an
alternative band limit (the maximum is 20).

@-m0@ requests the band limit to be removed. As many bands as
necessary are produced. However no key is produced as it won't fit! It
is useful for displaying creation time profiles with many bands.

<tag>@-p@</tag>
Use previous parameters. By default, the PostScript graph is
automatically scaled both horizontally and vertically so that it fills
the page.  However, when preparing a series of graphs for use in a
presentation, it is often useful to draw a new graph using the same
scale, shading and ordering as a previous one. The @-p@ flag causes
the graph to be drawn using the parameters determined by a previous
run of @hp2ps@ on @file@. These are extracted from
@file@@.aux@.

<tag>@-s@</tag> Use a small box for the title.

<tag>@-t<float>@</tag>
Normally trace elements which sum to a total of less than 1\% of the
profile are removed from the profile. The @-t@ option allows this
percentage to be modified (maximum 5\%). 

@-t0@ requests no trace elements to be removed from the profile,
ensuring that all the data will be displayed. 

<tag>@-?@</tag> Print out usage information.
</descrip>

<sect2>@stat2resid@---residency info from GC stats
<label id="stat2resid">
<p>
<nidx>stat2resid (utility)</nidx>
<nidx>GC stats---residency info</nidx>
<nidx>residency, from GC stats</nidx>

Usage:

<tscreen> <verb>
stat2resid [<file>[.stat] [<outfile>]]
</verb> </tscreen>

The program @stat2resid@<nidx>stat2resid</nidx> converts a detailed
garbage collection statistics file produced by the 
@-S@<nidx>-S RTS option</nidx> runtime option into a PostScript heap
residency graph. The garbage collection statistics file can be
produced without compiling your program for profiling.

By convention, the file to be processed by @stat2resid@ has a
@.stat@ extension. If the @<outfile>@ is not specified the
PostScript will be written to @<file>@@.resid.ps@. If
@<file>@ is omitted entirely, then the program behaves as a filter. 

The plot can not be produced from the statistics file for a
generational collector, though a suitable stats file can be produced
using the @-F2s@<nidx>-F2s RTS option</nidx> runtime option when the
program has been compiled for generational garbage collection (the
default).

@stat2resid@ is distributed in @ghc/utils/stat2resid@ in a GHC source
distribution.

%************************************************************************
%*									*
<sect1>Using ``ticky-ticky'' profiling (for implementors)
<label id="ticky-ticky">
<p>
<nidx>ticky-ticky profiling (implementors)</nidx>
%*									*
%************************************************************************

(ToDo: document properly.)

It is possible to compile Glasgow Haskell programs so that they will
count lots and lots of interesting things, e.g., number of updates,
number of data constructors entered, etc., etc.  We call this
``ticky-ticky'' profiling,<nidx>ticky-ticky profiling</nidx>%
<nidx>profiling, ticky-ticky</nidx> because that's the sound a Sun4 makes
when it is running up all those counters (<em>slowly</em>).

Ticky-ticky profiling is mainly intended for implementors; it is quite
separate from the main ``cost-centre'' profiling system, intended for
all users everywhere.

To be able to use ticky-ticky profiling, you will need to have built
appropriate libraries and things when you made the system.  See
``Customising what libraries to build,'' in the installation guide.

To get your compiled program to spit out the ticky-ticky numbers, use
a @-r@ RTS option<nidx>-r RTS option</nidx>.  See Section <ref
name="Running a compiled program" id="runtime-control">.

Compiling your program with the @-ticky@ switch yields an executable
that performs these counts.  Here is a sample ticky-ticky statistics
file, generated by the invocation @foo +RTS -rfoo.ticky@.

<tscreen> <verb>
foo +RTS -rfoo.ticky


ALLOCATIONS: 3964631 (11330900 words total: 3999476 admin, 6098829 goods, 1232595 slop)
				total words:	    2     3     4     5    6+
  69647 (  1.8%) function values		 50.0  50.0   0.0   0.0   0.0
2382937 ( 60.1%) thunks				  0.0  83.9  16.1   0.0   0.0
1477218 ( 37.3%) data values			 66.8  33.2   0.0   0.0   0.0
      0 (  0.0%) big tuples
      2 (  0.0%) black holes			  0.0 100.0   0.0   0.0   0.0
      0 (  0.0%) prim things
  34825 (  0.9%) partial applications		  0.0   0.0   0.0 100.0   0.0
      2 (  0.0%) thread state objects		  0.0   0.0   0.0   0.0 100.0

Total storage-manager allocations: 3647137 (11882004 words)
	[551104 words lost to speculative heap-checks]

STACK USAGE:

ENTERS: 9400092  of which 2005772 (21.3%) direct to the entry code
		  [the rest indirected via Node's info ptr]
1860318 ( 19.8%) thunks
3733184 ( 39.7%) data values
3149544 ( 33.5%) function values
		  [of which 1999880 (63.5%) bypassed arg-satisfaction chk]
 348140 (  3.7%) partial applications
 308906 (  3.3%) normal indirections
      0 (  0.0%) permanent indirections

RETURNS: 5870443
2137257 ( 36.4%) from entering a new constructor
		  [the rest from entering an existing constructor]
2349219 ( 40.0%) vectored [the rest unvectored]

RET_NEW:         2137257:  32.5% 46.2% 21.3%  0.0%  0.0%  0.0%  0.0%  0.0%  0.0%
RET_OLD:         3733184:   2.8% 67.9% 29.3%  0.0%  0.0%  0.0%  0.0%  0.0%  0.0%
RET_UNBOXED_TUP:       2:   0.0%  0.0%100.0%  0.0%  0.0%  0.0%  0.0%  0.0%  0.0%

RET_VEC_RETURN : 2349219:   0.0%  0.0%100.0%  0.0%  0.0%  0.0%  0.0%  0.0%  0.0%

UPDATE FRAMES: 2241725 (0 omitted from thunks)
SEQ FRAMES:    1
CATCH FRAMES:  1
UPDATES: 2241725
      0 (  0.0%) data values
  34827 (  1.6%) partial applications
		  [2 in place, 34825 allocated new space]
2206898 ( 98.4%) updates to existing heap objects (46 by squeezing)
UPD_CON_IN_NEW:         0:       0      0      0      0      0      0      0      0      0
UPD_PAP_IN_NEW:     34825:       0      0      0  34825      0      0      0      0      0

NEW GEN UPDATES: 2274700 ( 99.9%)

OLD GEN UPDATES: 1852 (  0.1%)

Total bytes copied during GC: 190096

**************************************************
3647137 ALLOC_HEAP_ctr
11882004 ALLOC_HEAP_tot
  69647 ALLOC_FUN_ctr
  69647 ALLOC_FUN_adm
  69644 ALLOC_FUN_gds
  34819 ALLOC_FUN_slp
  34831 ALLOC_FUN_hst_0
  34816 ALLOC_FUN_hst_1
      0 ALLOC_FUN_hst_2
      0 ALLOC_FUN_hst_3
      0 ALLOC_FUN_hst_4
2382937 ALLOC_UP_THK_ctr
      0 ALLOC_SE_THK_ctr
 308906 ENT_IND_ctr
      0 E!NT_PERM_IND_ctr requires +RTS -Z
[... lots more info omitted ...]
      0 GC_SEL_ABANDONED_ctr
      0 GC_SEL_MINOR_ctr
      0 GC_SEL_MAJOR_ctr
      0 GC_FAILED_PROMOTION_ctr
  47524 GC_WORDS_COPIED_ctr
</verb> </tscreen>

The formatting of the information above the row of asterisks is
subject to change, but hopefully provides a useful human-readable
summary.  Below the asterisks <em>all counters</em> maintained by the
ticky-ticky system are dumped, in a format intended to be
machine-readable: zero or more spaces, an integer, a space, the
counter name, and a newline.

In fact, not <em>all</em> counters are necessarily dumped; compile- or
run-time flags can render certain counters invalid.  In this case,
either the counter will simply not appear, or it will appear with a
modified counter name, possibly along with an explanation for the
omission (notice @ENT_PERM_IND_ctr@ appears with an inserted @!@
above).  Software analysing this output should always check that it
has the counters it expects.  Also, beware: some of the counters can
have <em>large</em> values!
<p>