b7e3fd3dedaee13cc9474767082a7556da44e9f2
[ghc-hetmet.git] / ghc / docs / users_guide / profiling.sgml
1 <chapter id="profiling">
2   <title>Profiling</Title>
3   <indexterm><primary>profiling</primary>
4   </indexterm>
5   <indexterm><primary>cost-centre profiling</primary></indexterm>
6
7   <para> Glasgow Haskell comes with a time and space profiling
8   system. Its purpose is to help you improve your understanding of
9   your program's execution behaviour, so you can improve it.</para>
10   
11   <para> Any comments, suggestions and/or improvements you have are
12   welcome.  Recommended &ldquo;profiling tricks&rdquo; would be
13   especially cool! </para>
14
15   <para>Profiling a program is a three-step process:</para>
16
17   <orderedlist>
18     <listitem>
19       <para> Re-compile your program for profiling with the
20       <literal>-prof</literal> option, and probably one of the
21       <literal>-auto</literal> or <literal>-auto-all</literal>
22       options.  These options are described in more detail in <xref
23       linkend="prof-compiler-options"> </para>
24       <indexterm><primary><literal>-prof</literal></primary>
25       </indexterm>
26       <indexterm><primary><literal>-auto</literal></primary>
27       </indexterm>
28       <indexterm><primary><literal>-auto-all</literal></primary>
29       </indexterm>
30     </listitem>
31
32     <listitem>
33       <para> Run your program with one of the profiling options, eg.
34       <literal>+RTS -p -RTS</literal>.  This generates a file of
35       profiling information.</para>
36       <indexterm><primary><option>-p</option></primary><secondary>RTS
37       option</secondary></indexterm>
38     </listitem>
39       
40     <listitem>
41       <para> Examine the generated profiling information, using one of
42       GHC's profiling tools.  The tool to use will depend on the kind
43       of profiling information generated.</para>
44     </listitem>
45     
46   </orderedlist>
47   
48   <sect1>
49     <title>Cost centres and cost-centre stacks</title>
50     
51     <para>GHC's profiling system assigns <firstterm>costs</firstterm>
52     to <firstterm>cost centres</firstterm>.  A cost is simply the time
53     or space required to evaluate an expression.  Cost centres are
54     program annotations around expressions; all costs incurred by the
55     annotated expression are assigned to the enclosing cost centre.
56     Furthermore, GHC will remember the stack of enclosing cost centres
57     for any given expression at run-time and generate a call-graph of
58     cost attributions.</para>
59
60     <para>Let's take a look at an example:</para>
61
62     <programlisting>
63 main = print (nfib 25)
64 nfib n = if n < 2 then 1 else nfib (n-1) + nfib (n-2)
65 </programlisting>
66
67     <para>Compile and run this program as follows:</para>
68
69     <screen>
70 $ ghc -prof -auto-all -o Main Main.hs
71 $ ./Main +RTS -p
72 121393
73 $
74 </screen>
75
76     <para>When a GHC-compiled program is run with the
77     <option>-p</option> RTS option, it generates a file called
78     <filename>&lt;prog&gt;.prof</filename>.  In this case, the file
79     will contain something like this:</para>
80
81 <screen>
82           Fri May 12 14:06 2000 Time and Allocation Profiling Report  (Final)
83
84            Main +RTS -p -RTS
85
86         total time  =        0.14 secs   (7 ticks @ 20 ms)
87         total alloc =   8,741,204 bytes  (excludes profiling overheads)
88
89 COST CENTRE          MODULE     %time %alloc
90
91 nfib                 Main       100.0  100.0
92
93
94                                               individual     inherited
95 COST CENTRE              MODULE      entries %time %alloc   %time %alloc
96
97 MAIN                     MAIN             0    0.0   0.0    100.0 100.0
98  main                    Main             0    0.0   0.0      0.0   0.0
99  CAF                     PrelHandle       3    0.0   0.0      0.0   0.0
100  CAF                     PrelAddr         1    0.0   0.0      0.0   0.0
101  CAF                     Main             6    0.0   0.0    100.0 100.0
102   main                   Main             1    0.0   0.0    100.0 100.0
103    nfib                  Main        242785  100.0 100.0    100.0 100.0
104 </screen>
105
106
107     <para>The first part of the file gives the program name and
108     options, and the total time and total memory allocation measured
109     during the run of the program (note that the total memory
110     allocation figure isn't the same as the amount of
111     <emphasis>live</emphasis> memory needed by the program at any one
112     time; the latter can be determined using heap profiling, which we
113     will describe shortly).</para>
114
115     <para>The second part of the file is a break-down by cost centre
116     of the most costly functions in the program.  In this case, there
117     was only one significant function in the program, namely
118     <function>nfib</function>, and it was responsible for 100&percnt;
119     of both the time and allocation costs of the program.</para>
120
121     <para>The third and final section of the file gives a profile
122     break-down by cost-centre stack.  This is roughly a call-graph
123     profile of the program.  In the example above, it is clear that
124     the costly call to <function>nfib</function> came from
125     <function>main</function>.</para>
126
127     <para>The time and allocation incurred by a given part of the
128     program is displayed in two ways: &ldquo;individual&rdquo;, which
129     are the costs incurred by the code covered by this cost centre
130     stack alone, and &ldquo;inherited&rdquo;, which includes the costs
131     incurred by all the children of this node.</para>
132
133     <para>The usefulness of cost-centre stacks is better demonstrated
134     by  modifying the example slightly:</para>
135
136     <programlisting>
137 main = print (f 25 + g 25)
138 f n  = nfib n
139 g n  = nfib (n `div` 2)
140 nfib n = if n < 2 then 1 else nfib (n-1) + nfib (n-2)
141 </programlisting>
142
143     <para>Compile and run this program as before, and take a look at
144     the new profiling results:</para>
145
146 <screen>
147 COST CENTRE              MODULE         scc  %time %alloc   %time %alloc
148
149 MAIN                     MAIN             0    0.0   0.0    100.0 100.0
150  main                    Main             0    0.0   0.0      0.0   0.0
151  CAF                     PrelHandle       3    0.0   0.0      0.0   0.0
152  CAF                     PrelAddr         1    0.0   0.0      0.0   0.0
153  CAF                     Main             9    0.0   0.0    100.0 100.0
154   main                   Main             1    0.0   0.0    100.0 100.0
155    g                     Main             1    0.0   0.0      0.0   0.2
156     nfib                 Main           465    0.0   0.2      0.0   0.2
157    f                     Main             1    0.0   0.0    100.0  99.8
158     nfib                 Main        242785  100.0  99.8    100.0  99.8
159 </screen>
160
161     <para>Now although we had two calls to <function>nfib</function>
162     in the program, it is immediately clear that it was the call from
163     <function>f</function> which took all the time.</para>
164
165     <para>The actual meaning of the various columns in the output is:</para>
166
167     <variablelist>
168       <varlistentry>
169         <term>entries</term>
170         <listitem>
171           <para>The number of times this particular point in the call
172           graph was entered.</para>
173         </listitem>
174       </varlistentry>
175
176       <varlistentry>
177         <term>individual &percnt;time</term>
178         <listitem>
179           <para>The percentage of the total run time of the program
180           spent at this point in the call graph.</para>
181         </listitem>
182       </varlistentry>
183
184       <varlistentry>
185         <term>individual &percnt;alloc</term>
186         <listitem>
187           <para>The percentage of the total memory allocations
188           (excluding profiling overheads) of the program made by this
189           call.</para>
190         </listitem>
191       </varlistentry>
192
193       <varlistentry>
194         <term>inherited &percnt;time</term>
195         <listitem>
196           <para>The percentage of the total run time of the program
197           spent below this point in the call graph.</para>
198         </listitem>
199       </varlistentry>
200
201       <varlistentry>
202         <term>inherited &percnt;alloc</term>
203         <listitem>
204           <para>The percentage of the total memory allocations
205           (excluding profiling overheads) of the program made by this
206           call and all of its sub-calls.</para>
207         </listitem>
208       </varlistentry>
209     </variablelist>
210
211     <para>In addition you can use the <Option>-P</Option> RTS option
212     <indexterm><primary><option>-P</option></primary></indexterm> to
213     get the following additional information:</para>
214
215     <variablelist>
216       <varlistentry>
217         <term><literal>ticks</literal></term>
218         <listitem>
219           <para>The raw number of time &ldquo;ticks&rdquo; which were
220           attributed to this cost-centre; from this, we get the
221           <literal>&percnt;time</literal> figure mentioned
222           above.</para>
223         </listitem>
224       </varlistentry>
225
226       <varlistentry>
227         <term><literal>bytes</literal></term>
228         <listItem>
229           <para>Number of bytes allocated in the heap while in this
230           cost-centre; again, this is the raw number from which we get
231           the <literal>&percnt;alloc</literal> figure mentioned
232           above.</para>
233         </listItem>
234       </varListEntry>
235     </variablelist>
236
237     <para>What about recursive functions, and mutually recursive
238     groups of functions?  Where are the costs attributed?  Well,
239     although GHC does keep information about which groups of functions
240     called each other recursively, this information isn't displayed in
241     the basic time and allocation profile, instead the call-graph is
242     flattened into a tree.  The XML profiling tool (described in <xref
243     linkend="prof-xml-tool">) will be able to display real loops in
244     the call-graph.</para>
245
246     <sect2><title>Inserting cost centres by hand</title>
247
248       <para>Cost centres are just program annotations.  When you say
249       <option>-auto-all</option> to the compiler, it automatically
250       inserts a cost centre annotation around every top-level function
251       in your program, but you are entirely free to add the cost
252       centre annotations yourself.</para>
253
254       <para>The syntax of a cost centre annotation is</para>
255
256       <programlisting>
257      {-# SCC "name" #-} &lt;expression&gt;
258 </programlisting>
259
260       <para>where <literal>"name"</literal> is an aribrary string,
261       that will become the name of your cost centre as it appears
262       in the profiling output, and
263       <literal>&lt;expression&gt;</literal> is any Haskell
264       expression.  An <literal>SCC</literal> annotation extends as
265       far to the right as possible when parsing.</para>
266
267     </sect2>
268
269     <sect2 id="prof-rules">
270       <title>Rules for attributing costs</title>
271
272       <para>The cost of evaluating any expression in your program is
273       attributed to a cost-centre stack using the following rules:</para>
274
275       <itemizedlist>
276         <listitem>
277           <para>If the expression is part of the
278           <firstterm>one-off</firstterm> costs of evaluating the
279           enclosing top-level definition, then costs are attributed to
280           the stack of lexically enclosing <literal>SCC</literal>
281           annotations on top of the special <literal>CAF</literal>
282           cost-centre. </para>
283         </listitem>
284
285         <listitem>
286           <para>Otherwise, costs are attributed to the stack of
287           lexically-enclosing <literal>SCC</literal> annotations,
288           appended to the cost-centre stack in effect at the
289           <firstterm>call site</firstterm> of the current top-level
290           definition<footnote> <para>The call-site is just the place
291           in the source code which mentions the particular function or
292           variable.</para></footnote>.  Notice that this is a recursive
293           definition.</para>
294         </listitem>
295       </itemizedlist>
296
297       <para>What do we mean by one-off costs?  Well, Haskell is a lazy
298       language, and certain expressions are only ever evaluated once.
299       For example, if we write:</para>
300
301       <programlisting>
302 x = nfib 25
303 </programlisting>
304
305       <para>then <varname>x</varname> will only be evaluated once (if
306       at all), and subsequent demands for <varname>x</varname> will
307       immediately get to see the cached result.  The definition
308       <varname>x</varname> is called a CAF (Constant Applicative
309       Form), because it has no arguments.</para>
310
311       <para>For the purposes of profiling, we say that the expression
312       <literal>nfib 25</literal> belongs to the one-off costs of
313       evaluating <varname>x</varname>.</para>
314
315       <para>Since one-off costs aren't strictly speaking part of the
316       call-graph of the program, they are attributed to a special
317       top-level cost centre, <literal>CAF</literal>.  There may be one
318       <literal>CAF</literal> cost centre for each module (the
319       default), or one for each top-level definition with any one-off
320       costs (this behaviour can be selected by giving GHC the
321       <option>-caf-all</option> flag).</para>
322
323       <indexterm><primary><literal>-caf-all</literal></primary>
324       </indexterm>
325
326       <para>If you think you have a weird profile, or the call-graph
327       doesn't look like you expect it to, feel free to send it (and
328       your program) to us at
329       <email>glasgow-haskell-bugs@haskell.org</email>.</para>
330
331     </sect2>
332   </sect1>
333
334   <sect1 id="prof-compiler-options">
335     <title>Compiler options for profiling</title>
336
337     <indexterm><primary>profiling</primary><secondary>options</secondary></indexterm>
338     <indexterm><primary>options</primary><secondary>for profiling</secondary></indexterm>
339
340     <variableList>
341       <varListEntry>
342         <term><Option>-prof</Option>:</Term>
343         <indexterm><primary><option>-prof</option></primary></indexterm>
344         <listItem>
345           <para> To make use of the profiling system
346           <emphasis>all</emphasis> modules must be compiled and linked
347           with the <option>-prof</option> option. Any
348           <literal>SCC</literal> annotations you've put in your source
349           will spring to life.</para>
350
351           <para> Without a <option>-prof</option> option, your
352           <literal>SCC</literal>s are ignored; so you can compile
353           <literal>SCC</literal>-laden code without changing
354           it.</para>
355         </listItem>
356       </varListEntry>
357     </variablelist>
358       
359     <para>There are a few other profiling-related compilation options.
360     Use them <emphasis>in addition to</emphasis>
361     <option>-prof</option>.  These do not have to be used consistently
362     for all modules in a program.</para>
363
364     <variablelist>
365       <varlistentry>
366         <term><option>-auto</option>:</Term>
367         <indexterm><primary><option>-auto</option></primary></indexterm>
368         <indexterm><primary>cost centres</primary><secondary>automatically inserting</secondary></indexterm>
369         <listItem>
370           <para> GHC will automatically add
371           <Function>&lowbar;scc&lowbar;</Function> constructs for all
372           top-level, exported functions.</para>
373         </listItem>
374       </varListEntry>
375       
376       <varListEntry>
377         <term><option>-auto-all</option>:</Term>
378         <indexterm><primary><option>-auto-all</option></primary></indexterm>
379         <listItem>
380           <para> <Emphasis>All</Emphasis> top-level functions,
381           exported or not, will be automatically
382           <Function>&lowbar;scc&lowbar;</Function>'d.</para>
383         </listItem>
384       </varListEntry>
385
386       <varListEntry>
387         <term><option>-caf-all</option>:</Term>
388         <indexterm><primary><option>-caf-all</option></primary></indexterm>
389         <listItem>
390           <para> The costs of all CAFs in a module are usually
391           attributed to one &ldquo;big&rdquo; CAF cost-centre. With
392           this option, all CAFs get their own cost-centre.  An
393           &ldquo;if all else fails&rdquo; option&hellip;</para>
394         </listItem>
395       </varListEntry>
396
397       <varListEntry>
398         <term><option>-ignore-scc</option>:</Term>
399         <indexterm><primary><option>-ignore-scc</option></primary></indexterm>
400         <listItem>
401           <para>Ignore any <Function>&lowbar;scc&lowbar;</Function>
402           constructs, so a module which already has
403           <Function>&lowbar;scc&lowbar;</Function>s can be compiled
404           for profiling with the annotations ignored.</para>
405         </listItem>
406       </varListEntry>
407
408     </variableList>
409
410   </sect1>
411
412   <sect1 id="prof-time-options">
413     <title>Time and allocation profiling</Title>
414
415     <para>To generate a time and allocation profile, give one of the
416     following RTS options to the compiled program when you run it (RTS
417     options should be enclosed between <literal>+RTS...-RTS</literal>
418     as usual):</para>
419
420     <variableList>
421       <varListEntry>
422         <term><Option>-p</Option> or <Option>-P</Option>:</Term>
423         <indexterm><primary><option>-p</option></primary></indexterm>
424         <indexterm><primary><option>-P</option></primary></indexterm>
425         <indexterm><primary>time profile</primary></indexterm>
426         <listItem>
427           <para>The <Option>-p</Option> option produces a standard
428           <Emphasis>time profile</Emphasis> report.  It is written
429           into the file
430           <Filename><replaceable>program</replaceable>.prof</Filename>.</para>
431
432           <para>The <Option>-P</Option> option produces a more
433           detailed report containing the actual time and allocation
434           data as well.  (Not used much.)</para>
435         </listitem>
436       </varlistentry>
437
438       <varlistentry>
439         <term><option>-px</option>:</term>
440         <indexterm><primary><option>-px</option></primary></indexterm>
441         <listitem>
442           <para>The <option>-px</option> option generates profiling
443           information in the XML format understood by our new
444           profiling tool, see <xref linkend="prof-xml-tool">.</para>
445         </listitem>
446       </varlistentry>
447
448       <varlistentry>
449         <term><option>-xc</option></term>
450         <indexterm><primary><option>-xc</option></primary><secondary>RTS
451         option</secondary></indexterm>
452         <listitem>
453           <para>This option makes use of the extra information
454           maintained by the cost-centre-stack profiler to provide
455           useful information about the location of runtime errors.
456           See <xref linkend="rts-options-debugging">.</para>
457         </listitem>
458       </varlistentry>
459
460     </variableList>
461     
462   </sect1>
463
464   <sect1 id="prof-heap">
465     <title>Profiling memory usage</title>
466
467     <para>In addition to profiling the time and allocation behaviour
468     of your program, you can also generate a graph of its memory usage
469     over time.  This is useful for detecting the causes of
470     <firstterm>space leaks</firstterm>, when your program holds on to
471     more memory at run-time that it needs to.  Space leaks lead to
472     longer run-times due to heavy garbage collector ativity, and may
473     even cause the program to run out of memory altogether.</para>
474
475     <para>To generate a heap profile from your program:</para>
476
477     <orderedlist>
478       <listitem>
479         <para>Compile the program for profiling (<xref
480         linkend="prof-compiler-options">).</para>
481       </listitem>
482       <listitem>
483         <para>Run it with one of the heap profiling options described
484         below (eg. <option>-hc</option> for a basic producer profile).
485         This generates the file
486         <filename><replaceable>prog</replaceable>.hp</filename>.</para>
487       </listitem>
488       <listitem>
489         <para>Run <command>hp2ps</command> to produce a Postscript
490         file,
491         <filename><replaceable>prog</replaceable>.ps</filename>.  The
492         <command>hp2ps</command> utility is described in detail in
493         <xref linkend="hp2ps">.</para> 
494       </listitem>
495       <listitem>
496         <para>Display the heap profile using a postscript viewer such
497         as <application>Ghostview</application>, or print it out on a
498         Postscript-capable printer.</para>
499       </listitem>
500     </orderedlist>
501
502     <sect2 id="rts-options-heap-prof">
503       <title>RTS options for heap profiling</title>
504
505       <para>There are several different kinds of heap profile that can
506       be generated.  All the different profile types yield a graph of
507       live heap against time, but they differ in how the live heap is
508       broken down into bands.  The following RTS options select which
509       break-down to use:</para>
510
511       <variablelist>
512         <varlistentry>
513           <term><option>-hc</option></term>
514           <indexterm><primary><option>-hc</option></primary><secondary>RTS
515           option</secondary></indexterm>
516           <listitem>
517             <para>Breaks down the graph by the cost-centre stack which
518             produced the data.</para>
519           </listitem>
520         </varlistentry>
521
522         <varlistentry>
523           <term><option>-hm</option></term>
524           <indexterm><primary><option>-hm</option></primary><secondary>RTS
525           option</secondary></indexterm>
526           <listitem>
527             <para>Break down the live heap by the module containing
528             the code which produced the data.</para>
529           </listitem>
530         </varlistentry>
531
532         <varlistentry>
533           <term><option>-hd</option></term>
534           <indexterm><primary><option>-hd</option></primary><secondary>RTS
535           option</secondary></indexterm>
536           <listitem>
537             <para>Breaks down the graph by <firstterm>closure
538             description</firstterm>.  For actual data, the description
539             is just the constructor name, for other closures it is a
540             compiler-generated string identifying the closure.</para>
541           </listitem>
542         </varlistentry>
543
544         <varlistentry>
545           <term><option>-hy</option></term>
546           <indexterm><primary><option>-hy</option></primary><secondary>RTS
547           option</secondary></indexterm>
548           <listitem>
549             <para>Breaks down the graph by
550             <firstterm>type</firstterm>.  For closures which have
551             function type or unknown/polymorphic type, the string will
552             represent an approximation to the actual type.</para>
553           </listitem>
554         </varlistentry>
555         
556         <varlistentry>
557           <term><option>-hr</option></term>
558           <indexterm><primary><option>-hr</option></primary><secondary>RTS
559           option</secondary></indexterm>
560           <listitem>
561             <para>Break down the graph by <firstterm>retainer
562             set</firstterm>.  Retainer profiling is described in more
563             detail below (<xref linkend="retainer-prof">).</para>
564           </listitem>
565         </varlistentry>
566
567         <varlistentry>
568           <term><option>-hb</option></term>
569           <indexterm><primary><option>-hb</option></primary><secondary>RTS
570           option</secondary></indexterm>
571           <listitem>
572             <para>Break down the graph by
573             <firstterm>biography</firstterm>.  Biographical profiling
574             is described in more detail below (<xref
575             linkend="biography-prof">).</para>
576           </listitem>
577         </varlistentry>
578       </variablelist>
579
580       <para>In addition, the profile can be restricted to heap data
581       which satisfies certain criteria - for example, you might want
582       to display a profile by type but only for data produced by a
583       certain module, or a profile by retainer for a certain type of
584       data.  Restrictions are specified as follows:</para>
585       
586       <variablelist>
587         <varlistentry>
588           <term><option>-hc</option><replaceable>name</replaceable>,...</term>
589           <indexterm><primary><option>-hc</option></primary><secondary>RTS
590           option</secondary></indexterm>
591           <listitem>
592             <para>Restrict the profile to closures produced by
593             cost-centre stacks with one of the specified cost centres
594             at the top.</para>
595           </listitem>
596         </varlistentry>
597
598         <varlistentry>
599           <term><option>-hC</option><replaceable>name</replaceable>,...</term>
600           <indexterm><primary><option>-hC</option></primary><secondary>RTS
601           option</secondary></indexterm>
602           <listitem>
603             <para>Restrict the profile to closures produced by
604             cost-centre stacks with one of the specified cost centres
605             anywhere in the stack.</para>
606           </listitem>
607         </varlistentry>
608
609         <varlistentry>
610           <term><option>-hm</option><replaceable>module</replaceable>,...</term>
611           <indexterm><primary><option>-hm</option></primary><secondary>RTS
612           option</secondary></indexterm>
613           <listitem>
614             <para>Restrict the profile to closures produced by the
615             specified modules.</para>
616           </listitem>
617         </varlistentry>
618
619         <varlistentry>
620           <term><option>-hd</option><replaceable>desc</replaceable>,...</term>
621           <indexterm><primary><option>-hd</option></primary><secondary>RTS
622           option</secondary></indexterm>
623           <listitem>
624             <para>Restrict the profile to closures with the specified
625             description strings.</para>
626           </listitem>
627         </varlistentry>
628
629         <varlistentry>
630           <term><option>-hy</option><replaceable>type</replaceable>,...</term>
631           <indexterm><primary><option>-hy</option></primary><secondary>RTS
632           option</secondary></indexterm>
633           <listitem>
634             <para>Restrict the profile to closures with the specified
635             types.</para>
636           </listitem>
637         </varlistentry>
638         
639         <varlistentry>
640           <term><option>-hr</option><replaceable>cc</replaceable>,...</term>
641           <indexterm><primary><option>-hr</option></primary><secondary>RTS
642           option</secondary></indexterm>
643           <listitem>
644             <para>Restrict the profile to closures with retainer sets
645             containing cost-centre stacks with one of the specified
646             cost centres at the top.</para>
647           </listitem>
648         </varlistentry>
649
650         <varlistentry>
651           <term><option>-hb</option><replaceable>bio</replaceable>,...</term>
652           <indexterm><primary><option>-hb</option></primary><secondary>RTS
653           option</secondary></indexterm>
654           <listitem>
655             <para>Restrict the profile to closures with one of the
656             specified biographies, where
657             <replaceable>bio</replaceable> is one of
658             <literal>lag</literal>, <literal>drag</literal>,
659             <literal>void</literal>, or <literal>use</literal>.</para>
660           </listitem>
661         </varlistentry>
662       </variablelist>
663
664       <para>For example, the following options will generate a
665       retainer profile restricted to <literal>Branch</literal> and
666       <literal>Leaf</literal> constructors:</para>
667
668 <screen>
669 <replaceable>prog</replaceable> +RTS -hr -hdBranch,Leaf
670 </screen>
671
672       <para>There can only be one "break-down" option
673       (eg. <option>-hr</option> in the example above), but there is no
674       limit on the number of further restrictions that may be applied.
675       All the options may be combined, with one exception: GHC doesn't
676       currently support mixing the <option>-hr</option> and
677       <option>-hb</option> options.</para>
678
679       <para>There's one more option which relates to heap
680       profiling:</para>
681
682       <variablelist>
683         <varlistentry>
684           <term><Option>-i<replaceable>secs</replaceable></Option>:</Term>
685           <indexterm><primary><option>-i</option></primary></indexterm>
686           <listItem>
687             <para> Set the profiling (sampling) interval to
688             <replaceable>secs</replaceable> seconds (the default is
689             0.1&nbsp;second).  Fractions are allowed: for example
690             <Option>-i0.2</Option> will get 5 samples per second.
691             This only affects heap profiling; time profiles are always
692             sampled on a 1/50 second frequency.</para>
693           </listItem>
694         </varlistentry>
695       </variablelist>
696
697     </sect2>
698     
699     <sect2 id="retainer-prof">
700       <title>Retainer Profiling</title>
701
702       <para>Retainer profiling is designed to help answer questions
703       like <quote>why is this data being retained?</quote>.  We start
704       by defining what we mean by a retainer:</para>
705
706       <blockquote>
707         <para>A retainer is either the system stack, or an unevaluated
708         closure (thunk).</para>
709       </blockquote>
710
711       <para>In particular, constructors are <emphasis>not</emphasis>
712       retainers.</para>
713
714       <para>An object A is retained by an object B if object A can be
715       reached by recursively following pointers starting from object
716       B but not meeting any other retainers on the way.  Each object
717       has one or more retainers, collectively called its
718       <firstterm>retainer set</firstterm>.</para>
719
720       <para>When retainer profiling is requested by giving the program
721       the <option>-hr</option> option, a graph is generated which is
722       broken down by retainer set.  A retainer set is displayed as a
723       set of cost-centre stacks; because this is usually too large to
724       fit on the profile graph, each retainer set is numbered and
725       shown abbreviated on the graph along with its number, and the
726       full list of retainer sets is dumped into the file
727       <filename><replaceable>prog</replaceable>.prof</filename>.</para>
728
729       <para>Retainer profiling requires multiple passes over the live
730       heap in order to discover the full retainer set for each
731       object, which can be quite slow.  So we set a limit on the
732       maximum size of a retainer set, where all retainer sets larger
733       than the maximum retainer set size are replaced by the special
734       set <literal>MANY</literal>.  The maximum set size defaults to 8
735       and can be altered with the <option>-R</option> RTS
736       option:</para>
737       
738       <variablelist>
739         <varlistentry>
740           <term><option>-R</option><replaceable>size</replaceable></term>
741           <listitem>
742             <para>Restrict the number of elements in a retainer set to
743             <replaceable>size</replaceable> (default 8).</para>
744           </listitem>
745         </varlistentry>
746       </variablelist>
747
748       <sect3>
749         <title>Hints for using retainer profiling</title>
750
751         <para>The definition of retainers is designed to reflect a
752         common cause of space leaks: a large structure is retained by
753         an unevaluated computation, and will be released once the
754         compuation is forced.  A good example is looking up a value in
755         a finite map, where unless the lookup is forced in a timely
756         manner the unevaluated lookup will cause the whole mapping to
757         be retained.  These kind of space leaks can often be
758         eliminated by forcing the relevant computations to be
759         performed eagerly, using <literal>seq</literal> or strictness
760         annotations on data constructor fields.</para>
761
762         <para>Often a particular data structure is being retained by a
763         chain of unevaluated closures, only the nearest of which will
764         be reported by retainer profiling - for example A retains B, B
765         retains C, and C retains a large structure.  There might be a
766         large number of Bs but only a single A, so A is really the one
767         we're interested in eliminating.  However, retainer profiling
768         will in this case report B as the retainer of the large
769         structure.  To move further up the chain of retainers, we can
770         ask for another retainer profile but this time restrict the
771         profile to B objects, so we get a profile of the retainers of
772         B:</para>
773
774 <screen>
775 <replaceable>prog</replaceable> +RTS -hr -hcB
776 </screen>
777         
778         <para>This trick isn't foolproof, because there might be other
779         B closures in the heap which aren't the retainers we are
780         interested in, but we've found this to be a useful technique
781         in most cases.</para>
782       </sect3>
783     </sect2>
784
785     <sect2 id="biography-prof">
786       <title>Biographical Profiling</title>
787
788       <para>A typical heap object may be in one of the following four
789       states at each point in its lifetime:</para>
790
791       <itemizedlist>
792         <listitem>
793           <para>The <firstterm>lag</firstterm> stage, which is the
794           time between creation and the first use of the
795           object,</para>
796         </listitem>
797         <listitem>
798           <para>the <firstterm>use</firstterm> stage, which lasts from
799           the first use until the last use of the object, and</para>
800         </listitem>
801         <listitem>
802           <para>The <firstterm>drag</firstterm> stage, which lasts
803           from the final use until the last reference to the object
804           is dropped.</para>
805         </listitem>
806         <listitem>
807           <para>An object which is never used is said to be in the
808           <firstterm>void</firstterm> state for its whole
809           lifetime.</para>
810         </listitem>
811       </itemizedlist>
812
813       <para>A biographical heap profile displays the portion of the
814       live heap in each of the four states listed above.  Usually the
815       most interesting states are the void and drag states: live heap
816       in these states is more likely to be wasted space than heap in
817       the lag or use states.</para>
818
819       <para>It is also possible to break down the heap in one or more
820       of these states by a different criteria, by restricting a
821       profile by biography.  For example, to show the portion of the
822       heap in the drag or void state by producer: </para>
823
824 <screen>
825 <replaceable>prog</replaceable> +RTS -hc -hbdrag,void
826 </screen>
827
828       <para>Once you know the producer or the type of the heap in the
829       drag or void states, the next step is usually to find the
830       retainer(s):</para>
831
832 <screen>
833 <replaceable>prog</replaceable> +RTS -hr -hc<replaceable>cc</replaceable>...
834 </screen>
835
836       <para>NOTE: this two stage process is required because GHC
837       cannot currently profile using both biographical and retainer
838       information simultaneously.</para>
839     </sect2>
840
841   </sect1>
842
843   <sect1 id="prof-xml-tool">
844     <title>Graphical time/allocation profile</title>
845
846     <para>You can view the time and allocation profiling graph of your
847     program graphically, using <command>ghcprof</command>.  This is a
848     new tool with GHC 4.08, and will eventually be the de-facto
849     standard way of viewing GHC profiles<footnote><para>Actually this
850     isn't true any more, we are working on a new tool for
851     displaying heap profiles using Gtk+HS, so
852     <command>ghcprof</command> may go away at some point in the future.</para>
853       </footnote></para>
854
855     <para>To run <command>ghcprof</command>, you need
856     <productname>daVinci</productname> installed, which can be
857     obtained from <ulink
858     url="http://www.informatik.uni-bremen.de/daVinci/"><citetitle>The Graph
859     Visualisation Tool daVinci</citetitle></ulink>.  Install one of
860     the binary
861     distributions<footnote><para><productname>daVinci</productname> is
862     sadly not open-source :-(.</para></footnote>, and set your
863     <envar>DAVINCIHOME</envar> environment variable to point to the
864     installation directory.</para>
865
866     <para><command>ghcprof</command> uses an XML-based profiling log
867     format, and you therefore need to run your program with a
868     different option: <option>-px</option>.  The file generated is
869     still called <filename>&lt;prog&gt;.prof</filename>.  To see the
870     profile, run <command>ghcprof</command> like this:</para>
871
872     <indexterm><primary><option>-px</option></primary></indexterm>
873
874 <screen>
875 $ ghcprof &lt;prog&gt;.prof
876 </screen>
877
878     <para>which should pop up a window showing the call-graph of your
879     program in glorious detail.  More information on using
880     <command>ghcprof</command> can be found at <ulink
881     url="http://www.dcs.warwick.ac.uk/people/academic/Stephen.Jarvis/profiler/index.html"><citetitle>The
882     Cost-Centre Stack Profiling Tool for
883     GHC</citetitle></ulink>.</para>
884
885   </sect1>
886
887   <sect1 id="hp2ps">
888     <title><command>hp2ps</command>--heap profile to PostScript</title>
889
890     <indexterm><primary><command>hp2ps</command></primary></indexterm>
891     <indexterm><primary>heap profiles</primary></indexterm>
892     <indexterm><primary>postscript, from heap profiles</primary></indexterm>
893     <indexterm><primary><option>-h&lt;break-down&gt;</option></primary></indexterm>
894     
895     <para>Usage:</para>
896     
897 <screen>
898 hp2ps [flags] [&lt;file&gt;[.hp]]
899 </screen>
900
901     <para>The program
902     <command>hp2ps</command><indexterm><primary>hp2ps
903     program</primary></indexterm> converts a heap profile as produced
904     by the <Option>-h&lt;break-down&gt;</Option> runtime option into a
905     PostScript graph of the heap profile. By convention, the file to
906     be processed by <command>hp2ps</command> has a
907     <filename>.hp</filename> extension. The PostScript output is
908     written to <filename>&lt;file&gt;@.ps</filename>. If
909     <filename>&lt;file&gt;</filename> is omitted entirely, then the
910     program behaves as a filter.</para>
911
912     <para><command>hp2ps</command> is distributed in
913     <filename>ghc/utils/hp2ps</filename> in a GHC source
914     distribution. It was originally developed by Dave Wakeling as part
915     of the HBC/LML heap profiler.</para>
916
917     <para>The flags are:</para>
918
919     <variableList>
920       
921       <varListEntry>
922         <term><Option>-d</Option></Term>
923         <listItem>
924           <para>In order to make graphs more readable,
925           <command>hp2ps</command> sorts the shaded bands for each
926           identifier. The default sort ordering is for the bands with
927           the largest area to be stacked on top of the smaller ones.
928           The <Option>-d</Option> option causes rougher bands (those
929           representing series of values with the largest standard
930           deviations) to be stacked on top of smoother ones.</para>
931         </listItem>
932       </varListEntry>
933
934       <varListEntry>
935         <term><Option>-b</Option></Term>
936         <listItem>
937           <para>Normally, <command>hp2ps</command> puts the title of
938           the graph in a small box at the top of the page. However, if
939           the JOB string is too long to fit in a small box (more than
940           35 characters), then <command>hp2ps</command> will choose to
941           use a big box instead.  The <Option>-b</Option> option
942           forces <command>hp2ps</command> to use a big box.</para>
943         </listItem>
944       </varListEntry>
945
946       <varListEntry>
947         <term><Option>-e&lt;float&gt;[in&verbar;mm&verbar;pt]</Option></Term>
948         <listItem>
949           <para>Generate encapsulated PostScript suitable for
950           inclusion in LaTeX documents.  Usually, the PostScript graph
951           is drawn in landscape mode in an area 9 inches wide by 6
952           inches high, and <command>hp2ps</command> arranges for this
953           area to be approximately centred on a sheet of a4 paper.
954           This format is convenient of studying the graph in detail,
955           but it is unsuitable for inclusion in LaTeX documents.  The
956           <Option>-e</Option> option causes the graph to be drawn in
957           portrait mode, with float specifying the width in inches,
958           millimetres or points (the default).  The resulting
959           PostScript file conforms to the Encapsulated PostScript
960           (EPS) convention, and it can be included in a LaTeX document
961           using Rokicki's dvi-to-PostScript converter
962           <command>dvips</command>.</para>
963         </listItem>
964       </varListEntry>
965
966       <varListEntry>
967         <term><Option>-g</Option></Term>
968         <listItem>
969           <para>Create output suitable for the <command>gs</command>
970           PostScript previewer (or similar). In this case the graph is
971           printed in portrait mode without scaling. The output is
972           unsuitable for a laser printer.</para>
973         </listItem>
974       </varListEntry>
975
976       <varListEntry>
977         <term><Option>-l</Option></Term>
978         <listItem>
979           <para>Normally a profile is limited to 20 bands with
980           additional identifiers being grouped into an
981           <literal>OTHER</literal> band. The <Option>-l</Option> flag
982           removes this 20 band and limit, producing as many bands as
983           necessary. No key is produced as it won't fit!. It is useful
984           for creation time profiles with many bands.</para>
985         </listItem>
986       </varListEntry>
987
988       <varListEntry>
989         <term><Option>-m&lt;int&gt;</Option></Term>
990         <listItem>
991           <para>Normally a profile is limited to 20 bands with
992           additional identifiers being grouped into an
993           <literal>OTHER</literal> band. The <Option>-m</Option> flag
994           specifies an alternative band limit (the maximum is
995           20).</para>
996
997           <para><Option>-m0</Option> requests the band limit to be
998           removed. As many bands as necessary are produced. However no
999           key is produced as it won't fit! It is useful for displaying
1000           creation time profiles with many bands.</para>
1001         </listItem>
1002       </varListEntry>
1003
1004       <varListEntry>
1005         <term><Option>-p</Option></Term>
1006         <listItem>
1007           <para>Use previous parameters. By default, the PostScript
1008           graph is automatically scaled both horizontally and
1009           vertically so that it fills the page.  However, when
1010           preparing a series of graphs for use in a presentation, it
1011           is often useful to draw a new graph using the same scale,
1012           shading and ordering as a previous one. The
1013           <Option>-p</Option> flag causes the graph to be drawn using
1014           the parameters determined by a previous run of
1015           <command>hp2ps</command> on <filename>file</filename>. These
1016           are extracted from <filename>file@.aux</filename>.</para>
1017         </listItem>
1018       </varListEntry>
1019
1020       <varListEntry>
1021         <term><Option>-s</Option></Term>
1022         <listItem>
1023           <para>Use a small box for the title.</para>
1024         </listItem>
1025       </varListEntry>
1026       
1027       <varListEntry>
1028         <term><Option>-t&lt;float&gt;</Option></Term>
1029         <listItem>
1030           <para>Normally trace elements which sum to a total of less
1031           than 1&percnt; of the profile are removed from the
1032           profile. The <option>-t</option> option allows this
1033           percentage to be modified (maximum 5&percnt;).</para>
1034
1035           <para><Option>-t0</Option> requests no trace elements to be
1036           removed from the profile, ensuring that all the data will be
1037           displayed.</para>
1038         </listItem>
1039       </varListEntry>
1040
1041       <varListEntry>
1042         <term><Option>-c</Option></Term>
1043         <listItem>
1044           <para>Generate colour output.</para>
1045         </listItem>
1046       </varListEntry>
1047       
1048       <varListEntry>
1049         <term><Option>-y</Option></Term>
1050         <listItem>
1051           <para>Ignore marks.</para>
1052         </listItem>
1053       </varListEntry>
1054       
1055       <varListEntry>
1056         <term><Option>-?</Option></Term>
1057         <listItem>
1058           <para>Print out usage information.</para>
1059         </listItem>
1060       </varListEntry>
1061     </variableList>
1062   </sect1>
1063
1064   <sect1 id="ticky-ticky">
1065     <title>Using &ldquo;ticky-ticky&rdquo; profiling (for implementors)</Title>
1066     <indexterm><primary>ticky-ticky profiling</primary></indexterm>
1067
1068     <para>(ToDo: document properly.)</para>
1069
1070     <para>It is possible to compile Glasgow Haskell programs so that
1071     they will count lots and lots of interesting things, e.g., number
1072     of updates, number of data constructors entered, etc., etc.  We
1073     call this &ldquo;ticky-ticky&rdquo;
1074     profiling,<indexterm><primary>ticky-ticky
1075     profiling</primary></indexterm> <indexterm><primary>profiling,
1076     ticky-ticky</primary></indexterm> because that's the sound a Sun4
1077     makes when it is running up all those counters
1078     (<Emphasis>slowly</Emphasis>).</para>
1079
1080     <para>Ticky-ticky profiling is mainly intended for implementors;
1081     it is quite separate from the main &ldquo;cost-centre&rdquo;
1082     profiling system, intended for all users everywhere.</para>
1083
1084     <para>To be able to use ticky-ticky profiling, you will need to
1085     have built appropriate libraries and things when you made the
1086     system.  See &ldquo;Customising what libraries to build,&rdquo; in
1087     the installation guide.</para>
1088
1089     <para>To get your compiled program to spit out the ticky-ticky
1090     numbers, use a <Option>-r</Option> RTS
1091     option<indexterm><primary>-r RTS option</primary></indexterm>.
1092     See <XRef LinkEnd="runtime-control">.</para>
1093
1094     <para>Compiling your program with the <Option>-ticky</Option>
1095     switch yields an executable that performs these counts.  Here is a
1096     sample ticky-ticky statistics file, generated by the invocation
1097     <command>foo +RTS -rfoo.ticky</command>.</para>
1098
1099 <screen>
1100  foo +RTS -rfoo.ticky
1101
1102
1103 ALLOCATIONS: 3964631 (11330900 words total: 3999476 admin, 6098829 goods, 1232595 slop)
1104                                 total words:        2     3     4     5    6+
1105   69647 (  1.8%) function values                 50.0  50.0   0.0   0.0   0.0
1106 2382937 ( 60.1%) thunks                           0.0  83.9  16.1   0.0   0.0
1107 1477218 ( 37.3%) data values                     66.8  33.2   0.0   0.0   0.0
1108       0 (  0.0%) big tuples
1109       2 (  0.0%) black holes                      0.0 100.0   0.0   0.0   0.0
1110       0 (  0.0%) prim things
1111   34825 (  0.9%) partial applications             0.0   0.0   0.0 100.0   0.0
1112       2 (  0.0%) thread state objects             0.0   0.0   0.0   0.0 100.0
1113
1114 Total storage-manager allocations: 3647137 (11882004 words)
1115         [551104 words lost to speculative heap-checks]
1116
1117 STACK USAGE:
1118
1119 ENTERS: 9400092  of which 2005772 (21.3%) direct to the entry code
1120                   [the rest indirected via Node's info ptr]
1121 1860318 ( 19.8%) thunks
1122 3733184 ( 39.7%) data values
1123 3149544 ( 33.5%) function values
1124                   [of which 1999880 (63.5%) bypassed arg-satisfaction chk]
1125  348140 (  3.7%) partial applications
1126  308906 (  3.3%) normal indirections
1127       0 (  0.0%) permanent indirections
1128
1129 RETURNS: 5870443
1130 2137257 ( 36.4%) from entering a new constructor
1131                   [the rest from entering an existing constructor]
1132 2349219 ( 40.0%) vectored [the rest unvectored]
1133
1134 RET_NEW:         2137257:  32.5% 46.2% 21.3%  0.0%  0.0%  0.0%  0.0%  0.0%  0.0%
1135 RET_OLD:         3733184:   2.8% 67.9% 29.3%  0.0%  0.0%  0.0%  0.0%  0.0%  0.0%
1136 RET_UNBOXED_TUP:       2:   0.0%  0.0%100.0%  0.0%  0.0%  0.0%  0.0%  0.0%  0.0%
1137
1138 RET_VEC_RETURN : 2349219:   0.0%  0.0%100.0%  0.0%  0.0%  0.0%  0.0%  0.0%  0.0%
1139
1140 UPDATE FRAMES: 2241725 (0 omitted from thunks)
1141 SEQ FRAMES:    1
1142 CATCH FRAMES:  1
1143 UPDATES: 2241725
1144       0 (  0.0%) data values
1145   34827 (  1.6%) partial applications
1146                   [2 in place, 34825 allocated new space]
1147 2206898 ( 98.4%) updates to existing heap objects (46 by squeezing)
1148 UPD_CON_IN_NEW:         0:       0      0      0      0      0      0      0      0      0
1149 UPD_PAP_IN_NEW:     34825:       0      0      0  34825      0      0      0      0      0
1150
1151 NEW GEN UPDATES: 2274700 ( 99.9%)
1152
1153 OLD GEN UPDATES: 1852 (  0.1%)
1154
1155 Total bytes copied during GC: 190096
1156
1157 **************************************************
1158 3647137 ALLOC_HEAP_ctr
1159 11882004 ALLOC_HEAP_tot
1160   69647 ALLOC_FUN_ctr
1161   69647 ALLOC_FUN_adm
1162   69644 ALLOC_FUN_gds
1163   34819 ALLOC_FUN_slp
1164   34831 ALLOC_FUN_hst_0
1165   34816 ALLOC_FUN_hst_1
1166       0 ALLOC_FUN_hst_2
1167       0 ALLOC_FUN_hst_3
1168       0 ALLOC_FUN_hst_4
1169 2382937 ALLOC_UP_THK_ctr
1170       0 ALLOC_SE_THK_ctr
1171  308906 ENT_IND_ctr
1172       0 E!NT_PERM_IND_ctr requires +RTS -Z
1173 [... lots more info omitted ...]
1174       0 GC_SEL_ABANDONED_ctr
1175       0 GC_SEL_MINOR_ctr
1176       0 GC_SEL_MAJOR_ctr
1177       0 GC_FAILED_PROMOTION_ctr
1178   47524 GC_WORDS_COPIED_ctr
1179 </screen>
1180
1181     <para>The formatting of the information above the row of asterisks
1182     is subject to change, but hopefully provides a useful
1183     human-readable summary.  Below the asterisks <Emphasis>all
1184     counters</Emphasis> maintained by the ticky-ticky system are
1185     dumped, in a format intended to be machine-readable: zero or more
1186     spaces, an integer, a space, the counter name, and a newline.</para>
1187
1188     <para>In fact, not <Emphasis>all</Emphasis> counters are
1189     necessarily dumped; compile- or run-time flags can render certain
1190     counters invalid.  In this case, either the counter will simply
1191     not appear, or it will appear with a modified counter name,
1192     possibly along with an explanation for the omission (notice
1193     <literal>ENT&lowbar;PERM&lowbar;IND&lowbar;ctr</literal> appears
1194     with an inserted <literal>!</literal> above).  Software analysing
1195     this output should always check that it has the counters it
1196     expects.  Also, beware: some of the counters can have
1197     <Emphasis>large</Emphasis> values!</para>
1198
1199   </sect1>
1200
1201 </chapter>
1202
1203 <!-- Emacs stuff:
1204      ;;; Local Variables: ***
1205      ;;; mode: sgml ***
1206      ;;; sgml-parent-document: ("users_guide.sgml" "book" "chapter") ***
1207      ;;; End: ***
1208  -->