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
  34       <literal>-p</literal> or <literal>-h</literal>.  This generates
  35       a file of profiling information.</para>
  36       <indexterm><primary><literal>-p</literal></primary><secondary>RTS
  37       option</secondary></indexterm>
  38       <indexterm><primary><literal>-h</literal></primary><secondary>RTS
  39       option</secondary></indexterm>
  40     </listitem>
  41
  42     <listitem>
  43       <para> Examine the generated profiling information, using one of
  44       GHC's profiling tools.  The tool to use will depend on the kind
  45       of profiling information generated.</para>
  46     </listitem>
  47
  48   </orderedlist>
  49
  50   <sect1>
  51     <title>Cost centres and cost-centre stacks</title>
  52
  53     <para>GHC's profiling system assigns <firstterm>costs</firstterm>
  54     to <firstterm>cost centres</firstterm>.  A cost is simply the time
  55     or space required to evaluate an expression.  Cost centres are
  56     program annotations around expressions; all costs incurred by the
  57     annotated expression are assigned to the enclosing cost centre.
  58     Furthermore, GHC will remember the stack of enclosing cost centres
  59     for any given expression at run-time and generate a call-graph of
  60     cost attributions.</para>
  61
  62     <para>Let's take a look at an example:</para>
  63
  64     <programlisting>
  65 main = print (nfib 25)
  66 nfib n = if n < 2 then 1 else nfib (n-1) + nfib (n-2)
  67 </programlisting>
  68
  69     <para>Compile and run this program as follows:</para>
  70
  71     <screen>
  72 $ ghc -prof -auto-all -o Main Main.hs
  73 $ ./Main +RTS -p
  74 121393
  75 $
  76 </screen>
  77
  78     <para>When a GHC-compiled program is run with the
  79     <option>-p</option> RTS option, it generates a file called
  80     <filename>&lt;prog&gt;.prof</filename>.  In this case, the file
  81     will contain something like this:</para>
  82
  83 <screen>
  84           Fri May 12 14:06 2000 Time and Allocation Profiling Report  (Final)
  85
  86            Main +RTS -p -RTS
  87
  88         total time  =        0.14 secs   (7 ticks @ 20 ms)
  89         total alloc =   8,741,204 bytes  (excludes profiling overheads)
  90
  91 COST CENTRE          MODULE     %time %alloc
  92
  93 nfib                 Main       100.0  100.0
  94
  95
  96                                               individual     inherited
  97 COST CENTRE              MODULE         scc  %time %alloc   %time %alloc
  98
  99 MAIN                     MAIN             0    0.0   0.0    100.0 100.0
 100  main                    Main             0    0.0   0.0      0.0   0.0
 101  CAF                     PrelHandle       3    0.0   0.0      0.0   0.0
 102  CAF                     PrelAddr         1    0.0   0.0      0.0   0.0
 103  CAF                     Main             6    0.0   0.0    100.0 100.0
 104   main                   Main             1    0.0   0.0    100.0 100.0
 105    nfib                  Main        242785  100.0 100.0    100.0 100.0
 106 </screen>
 107
 108
 109     <para>The first part of the file gives the program name and
 110     options, and the total time and total memory allocation measured
 111     during the run of the program (note that the total memory
 112     allocation figure isn't the same as the amount of
 113     <emphasis>live</emphasis> memory needed by the program at any one
 114     time; the latter can be determined using heap profiling, which we
 115     will describe shortly).</para>
 116
 117     <para>The second part of the file is a break-down by cost centre
 118     of the most costly functions in the program.  In this case, there
 119     was only one significant function in the program, namely
 120     <function>nfib</function>, and it was responsible for 100&percnt;
 121     of both the time and allocation costs of the program.</para>
 122
 123     <para>The third and final section of the file gives a profile
 124     break-down by cost-centre stack.  This is roughly a call-graph
 125     profile of the program.  In the example above, it is clear that
 126     the costly call to <function>nfib</function> came from
 127     <function>main</function>.</para>
 128
 129     <para>The time and allocation incurred by a given part of the
 130     program is displayed in two ways: &ldquo;individual&rdquo;, which
 131     are the costs incurred by the code covered by this cost centre
 132     stack alone, and &ldquo;inherited&rdquo;, which includes the costs
 133     incurred by all the children of this node.</para>
 134
 135     <para>The usefulness of cost-centre stacks is better demonstrated
 136     by  modifying the example slightly:</para>
 137
 138     <programlisting>
 139 main = print (f 25 + g 25)
 140 f n  = nfib n
 141 g n  = nfib (n `div` 2)
 142 nfib n = if n < 2 then 1 else nfib (n-1) + nfib (n-2)
 143 </programlisting>
 144
 145     <para>Compile and run this program as before, and take a look at
 146     the new profiling results:</para>
 147
 148 <screen>
 149 COST CENTRE              MODULE         scc  %time %alloc   %time %alloc
 150
 151 MAIN                     MAIN             0    0.0   0.0    100.0 100.0
 152  main                    Main             0    0.0   0.0      0.0   0.0
 153  CAF                     PrelHandle       3    0.0   0.0      0.0   0.0
 154  CAF                     PrelAddr         1    0.0   0.0      0.0   0.0
 155  CAF                     Main             9    0.0   0.0    100.0 100.0
 156   main                   Main             1    0.0   0.0    100.0 100.0
 157    g                     Main             1    0.0   0.0      0.0   0.2
 158     nfib                 Main           465    0.0   0.2      0.0   0.2
 159    f                     Main             1    0.0   0.0    100.0  99.8
 160     nfib                 Main        242785  100.0  99.8    100.0  99.8
 161 </screen>
 162
 163     <para>Now although we had two calls to <function>nfib</function>
 164     in the program, it is immediately clear that it was the call from
 165     <function>f</function> which took all the time.</para>
 166
 167     <para>The actual meaning of the various columns in the output is:</para>
 168
 169     <variablelist>
 170       <varlistentry>
 171         <term>entries</term>
 172         <listitem>
 173           <para>The number of times this particular point in the call
 174           graph was entered.</para>
 175         </listitem>
 176       </varlistentry>
 177
 178       <varlistentry>
 179         <term>individual &percnt;time</term>
 180         <listitem>
 181           <para>The percentage of the total run time of the program
 182           spent at this point in the call graph.</para>
 183         </listitem>
 184       </varlistentry>
 185
 186       <varlistentry>
 187         <term>individual &percnt;alloc</term>
 188         <listitem>
 189           <para>The percentage of the total memory allocations
 190           (excluding profiling overheads) of the program made by this
 191           call.</para>
 192         </listitem>
 193       </varlistentry>
 194
 195       <varlistentry>
 196         <term>inherited &percnt;time</term>
 197         <listitem>
 198           <para>The percentage of the total run time of the program
 199           spent below this point in the call graph.</para>
 200         </listitem>
 201       </varlistentry>
 202
 203       <varlistentry>
 204         <term>inherited &percnt;alloc</term>
 205         <listitem>
 206           <para>The percentage of the total memory allocations
 207           (excluding profiling overheads) of the program made by this
 208           call and all of its sub-calls.</para>
 209         </listitem>
 210       </varlistentry>
 211     </variablelist>
 212
 213     <para>In addition you can use the <Option>-P</Option> RTS option
 214     <indexterm><primary><option>-P</option></primary></indexterm> to
 215     get the following additional information:</para>
 216
 217     <variablelist>
 218       <varlistentry>
 219         <term><literal>ticks</literal></term>
 220         <listitem>
 221           <Para>The raw number of time &ldquo;ticks&rdquo; which were
 222           attributed to this cost-centre; from this, we get the
 223           <literal>&percnt;time</literal> figure mentioned
 224           above.</Para>
 225         </listitem>
 226       </varlistentry>
 227
 228       <varlistentry>
 229         <term><literal>bytes</literal></term>
 230         <listItem>
 231           <Para>Number of bytes allocated in the heap while in this
 232           cost-centre; again, this is the raw number from which we get
 233           the <literal>&percnt;alloc</literal> figure mentioned
 234           above.</Para>
 235         </listItem>
 236       </varListEntry>
 237     </variablelist>
 238
 239     <para>What about recursive functions, and mutually recursive
 240     groups of functions?  Where are the costs attributed?  Well,
 241     although GHC does keep information about which groups of functions
 242     called each other recursively, this information isn't displayed in
 243     the basic time and allocation profile, instead the call-graph is
 244     flattened into a tree.  The XML profiling tool (described in <xref
 245     linkend="prof-xml-tool">) will be able to display real loops in
 246     the call-graph.</para>
 247
 248     <sect2><title>Inserting cost centres by hand</title>
 249
 250       <para>Cost centres are just program annotations.  When you say
 251       <option>-auto-all</option> to the compiler, it automatically
 252       inserts a cost centre annotation around every top-level function
 253       in your program, but you are entirely free to add the cost
 254       centre annotations yourself.</para>
 255
 256       <para>The syntax of a cost centre annotation is</para>
 257
 258       <programlisting>
 259      _scc_ "name" &lt;expression&gt;
 260 </programlisting>
 261
 262       <para>where <literal>"name"</literal> is an aribrary string,
 263       that will become the name of your cost centre as it appears
 264       in the profiling output, and
 265       <literal>&lt;expression&gt;</literal> is any Haskell
 266       expression.  An <literal>_scc_</literal> annotation extends as
 267       far to the right as possible when parsing.</para>
 268
 269     </sect2>
 270
 271     <sect2 id="prof-rules">
 272       <title>Rules for attributing costs</title>
 273
 274       <para>The cost of evaluating any expression in your program is
 275       attributed to a cost-centre stack using the following rules:</para>
 276
 277       <itemizedlist>
 278         <listitem>
 279           <para>If the expression is part of the
 280           <firstterm>one-off</firstterm> costs of evaluating the
 281           enclosing top-level definition, then costs are attributed to
 282           the stack of lexically enclosing <literal>_scc_</literal>
 283           annotations on top of the special <literal>CAF</literal>
 284           cost-centre. </para>
 285         </listitem>
 286
 287         <listitem>
 288           <para>Otherwise, costs are attributed to the stack of
 289           lexically-enclosing <literal>_scc_</literal> annotations,
 290           appended to the cost-centre stack in effect at the
 291           <firstterm>call site</firstterm> of the current top-level
 292           definition<footnote> <para>The call-site is just the place
 293           in the source code which mentions the particular function or
 294           variable.</para></footnote>.  Notice that this is a recursive
 295           definition.</para>
 296         </listitem>
 297       </itemizedlist>
 298
 299       <para>What do we mean by one-off costs?  Well, Haskell is a lazy
 300       language, and certain expressions are only ever evaluated once.
 301       For example, if we write:</para>
 302
 303       <programlisting>
 304 x = nfib 25
 305 </programlisting>
 306
 307       <para>then <varname>x</varname> will only be evaluated once (if
 308       at all), and subsequent demands for <varname>x</varname> will
 309       immediately get to see the cached result.  The definition
 310       <varname>x</varname> is called a CAF (Constant Applicative
 311       Form), because it has no arguments.</para>
 312
 313       <para>For the purposes of profiling, we say that the expression
 314       <literal>nfib 25</literal> belongs to the one-off costs of
 315       evaluating <varname>x</varname>.</para>
 316
 317       <para>Since one-off costs aren't strictly speaking part of the
 318       call-graph of the program, they are attributed to a special
 319       top-level cost centre, <literal>CAF</literal>.  There may be one
 320       <literal>CAF</literal> cost centre for each module (the
 321       default), or one for each top-level definition with any one-off
 322       costs (this behaviour can be selected by giving GHC the
 323       <option>-caf-all</option> flag).</para>
 324
 325       <indexterm><primary><literal>-caf-all</literal></primary>
 326       </indexterm>
 327
 328       <para>If you think you have a weird profile, or the call-graph
 329       doesn't look like you expect it to, feel free to send it (and
 330       your program) to us at
 331       <email>glasgow-haskell-bugs@haskell.org</email>.</para>
 332
 333     </sect2>
 334   </sect1>
 335
 336   <sect1 id="prof-heap">
 337     <title>Profiling memory usage</title>
 338
 339     <para>In addition to profiling the time and allocation behaviour
 340     of your program, you can also generate a graph of its memory usage
 341     over time.  This is useful for detecting the causes of
 342     <firstterm>space leaks</firstterm>, when your program holds on to
 343     more memory at run-time that it needs to.  Space leaks lead to
 344     longer run-times due to heavy garbage collector ativity, and may
 345     even cause the program to run out of memory altogether.</para>
 346
 347     <para>To generate a heap profile from your program, compile it as
 348     before, but this time run it with the <option>-h</option> runtime
 349     option.  This generates a file
 350     <filename>&lt;prog&gt;.hp</filename> file, which you then process
 351     with <command>hp2ps</command> to produce a Postscript file
 352     <filename>&lt;prog&gt;.ps</filename>.  The Postscript file can be
 353     viewed with something like <command>ghostview</command>, or
 354     printed out on a Postscript-compatible printer.</para>
 355
 356     <para>For the RTS options that control the kind of heap profile
 357     generated, see <xref linkend="prof-rts-options">.  Details on the
 358     usage of the <command>hp2ps</command> program are given in <xref
 359     linkend="hp2ps"></para>
 360
 361   </sect1>
 362
 363   <sect1 id="prof-xml-tool">
 364     <title>Graphical time/allocation profile</title>
 365
 366     <para>You can view the time and allocation profiling graph of your
 367     program graphically, using <command>ghcprof</command>.  This is a
 368     new tool with GHC 4.07, and will eventually be the de-facto
 369     standard way of viewing GHC profiles.</para>
 370
 371     <para>To run <command>ghcprof</command>, you need
 372     <productname>daVinci</productname> installed, which can be
 373     obtained from <ulink
 374     url="http://www.tzi.de/~davinci/"><citetitle>The Graph
 375     Visualisation Tool daVinci</citetitle></ulink>.  Install one of
 376     the binary
 377     distributions<footnote><para><productname>daVinci</productname> is
 378     sadly not open-source :-(.</para></footnote>, and set your
 379     <envar>DAVINCIHOME</envar> environment variable to point to the
 380     installation directory.</para>
 381
 382     <para><command>ghcprof</command> uses an XML-based profiling log
 383     format, and you therefore need to run your program with a
 384     different option: <option>-px</option>.  The file generated is
 385     still called <filename>&lt;prog&gt;.prof</filename>.  To see the
 386     profile, run <command>ghcprof</command> like this:</para>
 387
 388     <indexterm><primary><option>-px</option></primary></indexterm>
 389
 390 <screen>
 391 $ ghcprof &lt;prog&gt;.prof
 392 </screen>
 393
 394     <para>which should pop up a window showing the call-graph of your
 395     program in glorious detail.  More information on using
 396     <command>ghcprof</command> can be found at <ulink
 397     url="http://www.dcs.warwick.ac.uk/people/academic/Stephen.Jarvis/profiler/index.html"><citetitle>The
 398     Cost-Centre Stack Profiling Tool for
 399     GHC</citetitle></ulink>.</para>
 400
 401   </sect1>
 402
 403   <sect1 id="prof-compiler-options">
 404     <title>Compiler options for profiling</title>
 405
 406     <indexterm><primary>profiling</primary><secondary>options</secondary></indexterm>
 407     <indexterm><primary>options</primary><secondary>for profiling</secondary></indexterm>
 408
 409     <Para> To make use of the cost centre profiling system
 410     <Emphasis>all</Emphasis> modules must be compiled and linked with
 411     the <Option>-prof</Option> option. Any
 412     <Function>&lowbar;scc&lowbar;</Function> constructs you've put in
 413     your source will spring to life.</Para>
 414
 415     <indexterm><primary><literal>-prof</literal></primary></indexterm>
 416
 417     <Para> Without a <Option>-prof</Option> option, your
 418     <Function>&lowbar;scc&lowbar;</Function>s are ignored; so you can
 419     compiled <Function>&lowbar;scc&lowbar;</Function>-laden code
 420     without changing it.</Para>
 421
 422     <Para>There are a few other profiling-related compilation options.
 423     Use them <Emphasis>in addition to</Emphasis>
 424     <Option>-prof</Option>.  These do not have to be used consistently
 425     for all modules in a program.</Para>
 426
 427     <variableList>
 428
 429       <varListEntry>
 430         <term><Option>-auto</Option>:</Term>
 431         <indexterm><primary><literal>-auto</literal></primary></indexterm>
 432         <indexterm><primary>cost centres</primary><secondary>automatically inserting</secondary></indexterm>
 433         <listItem>
 434           <Para> GHC will automatically add
 435           <Function>&lowbar;scc&lowbar;</Function> constructs for all
 436           top-level, exported functions.</Para>
 437         </listItem>
 438       </varListEntry>
 439
 440       <varListEntry>
 441         <term><Option>-auto-all</Option>:</Term>
 442         <indexterm><primary><literal>-auto-all</literal></primary></indexterm>
 443         <listItem>
 444           <Para> <Emphasis>All</Emphasis> top-level functions,
 445           exported or not, will be automatically
 446           <Function>&lowbar;scc&lowbar;</Function>'d.</Para>
 447         </listItem>
 448       </varListEntry>
 449
 450       <varListEntry>
 451         <term><Option>-caf-all</Option>:</Term>
 452         <indexterm><primary><literal>-caf-all</literal></primary></indexterm>
 453         <listItem>
 454           <Para> The costs of all CAFs in a module are usually
 455           attributed to one &ldquo;big&rdquo; CAF cost-centre. With
 456           this option, all CAFs get their own cost-centre.  An
 457           &ldquo;if all else fails&rdquo; option&hellip;</Para>
 458         </listItem>
 459       </varListEntry>
 460
 461       <varListEntry>
 462         <term><Option>-ignore-scc</Option>:</Term>
 463         <indexterm><primary><literal>-ignore-scc</literal></primary></indexterm>
 464         <listItem>
 465           <Para>Ignore any <Function>&lowbar;scc&lowbar;</Function>
 466           constructs, so a module which already has
 467           <Function>&lowbar;scc&lowbar;</Function>s can be compiled
 468           for profiling with the annotations ignored.</Para>
 469         </listItem>
 470       </varListEntry>
 471
 472     </variableList>
 473
 474   </sect1>
 475
 476   <sect1 id="prof-rts-options">
 477     <title>Runtime options for profiling</Title>
 478
 479     <indexterm><primary>profiling RTS options</primary></indexterm>
 480     <indexterm><primary>RTS options, for profiling</primary></indexterm>
 481
 482     <Para>It isn't enough to compile your program for profiling with
 483     <Option>-prof</Option>!</Para>
 484
 485     <Para>When you <Emphasis>run</Emphasis> your profiled program, you
 486     must tell the runtime system (RTS) what you want to profile (e.g.,
 487     time and/or space), and how you wish the collected data to be
 488     reported.  You also may wish to set the sampling interval used in
 489     time profiling.</Para>
 490
 491     <Para>Executive summary: <command>./a.out +RTS -pT</command>
 492     produces a time profile in <Filename>a.out.prof</Filename>;
 493     <command>./a.out +RTS -hC</command> produces space-profiling info
 494     which can be mangled by <command>hp2ps</command> and viewed with
 495     <command>ghostview</command> (or equivalent).</Para>
 496
 497     <Para>Profiling runtime flags are passed to your program between
 498     the usual <Option>+RTS</Option> and <Option>-RTS</Option>
 499     options.</Para>
 500
 501     <variableList>
 502
 503       <varListEntry>
 504         <term><Option>-p</Option> or <Option>-P</Option>:</Term>
 505         <indexterm><primary><option>-p</option></primary></indexterm>
 506         <indexterm><primary><option>-P</option></primary></indexterm>
 507         <indexterm><primary>time profile</primary></indexterm>
 508         <listItem>
 509           <Para>The <Option>-p</Option> option produces a standard
 510           <Emphasis>time profile</Emphasis> report.  It is written
 511           into the file
 512           <Filename>&lt;program&gt;.prof</Filename>.</Para>
 513
 514           <Para>The <Option>-P</Option> option produces a more
 515           detailed report containing the actual time and allocation
 516           data as well.  (Not used much.)</Para>
 517         </listitem>
 518       </varlistentry>
 519
 520       <varlistentry>
 521         <term><option>-px</option>:</term>
 522         <indexterm><primary><option>-px</option></primary></indexterm>
 523         <listitem>
 524           <para>The <option>-px</option> option generates profiling
 525           information in the XML format understood by our new
 526           profiling tool, see <xref linkend="prof-xml-tool">.</para>
 527         </listitem>
 528       </varlistentry>
 529
 530       <varlistentry>
 531         <term><Option>-i&lt;secs&gt;</Option>:</Term>
 532         <indexterm><primary><option>-i</option></primary></indexterm>
 533         <listItem>
 534           <Para> Set the profiling (sampling) interval to
 535           <literal>&lt;secs&gt;</literal> seconds (the default is
 536           1&nbsp;second).  Fractions are allowed: for example
 537           <Option>-i0.2</Option> will get 5 samples per second.  This
 538           only affects heap profiling; time profiles are always
 539           sampled on a 1/50 second frequency.</Para>
 540         </listItem>
 541       </varlistentry>
 542
 543       <varlistentry>
 544         <term><Option>-h&lt;break-down&gt;</Option>:</Term>
 545         <indexterm><primary><option>-h&lt;break-down&gt</option></primary></indexterm>
 546         <indexterm><primary>heap profile</primary></indexterm>
 547         <listItem>
 548           <Para>Produce a detailed <Emphasis>heap profile</Emphasis>
 549           of the heap occupied by live closures. The profile is
 550           written to the file <Filename>&lt;program&gt;.hp</Filename>
 551           from which a PostScript graph can be produced using
 552           <command>hp2ps</command> (see <XRef
 553           LinkEnd="hp2ps">).</Para>
 554
 555           <Para>The heap space profile may be broken down by different
 556           criteria:</para>
 557
 558           <variableList>
 559
 560             <varListEntry>
 561               <term><Option>-hC</Option>:</Term>
 562               <listItem>
 563                 <Para>cost centre which produced the closure (the
 564                 default).</Para>
 565               </listItem>
 566             </varListEntry>
 567
 568             <varListEntry>
 569               <term><Option>-hM</Option>:</Term>
 570               <listItem>
 571                 <Para>cost centre module which produced the
 572                 closure.</Para>
 573               </listItem>
 574             </varListEntry>
 575
 576             <varListEntry>
 577               <term><Option>-hD</Option>:</Term>
 578               <listItem>
 579                 <Para>closure description&mdash;a string describing
 580                 the closure.</Para>
 581               </listItem>
 582             </varListEntry>
 583
 584             <varListEntry>
 585               <term><Option>-hY</Option>:</Term>
 586               <listItem>
 587                 <Para>closure type&mdash;a string describing the
 588                 closure's type.</Para>
 589               </listItem>
 590             </varListEntry>
 591           </variableList>
 592
 593         </listItem>
 594       </varListEntry>
 595
 596       <varlistentry>
 597         <term><option>-hx</option>:</term>
 598         <indexterm><primary><option>-hx</option></primary></indexterm>
 599         <listitem>
 600           <para>The <option>-hx</option> option generates heap
 601           profiling information in the XML format understood by our
 602           new profiling tool (NOTE: heap profiling with the new tool
 603           is not yet working!  Use <command>hp2ps</command>-style heap
 604           profiling for the time being).</para>
 605         </listitem>
 606       </varlistentry>
 607
 608     </variableList>
 609
 610   </sect1>
 611
 612   <sect1 id="hp2ps">
 613     <title><command>hp2ps</command>--heap profile to PostScript</title>
 614
 615     <indexterm><primary><command>hp2ps</command></primary></indexterm>
 616     <indexterm><primary>heap profiles</primary></indexterm>
 617     <indexterm><primary>postscript, from heap profiles</primary></indexterm>
 618     <indexterm><primary><option>-h&lt;break-down&gt;</option></primary></indexterm>
 619
 620     <para>Usage:</para>
 621
 622 <screen>
 623 hp2ps [flags] [&lt;file&gt;[.hp]]
 624 </screen>
 625
 626     <para>The program
 627     <command>hp2ps</command><indexterm><primary>hp2ps
 628     program</primary></indexterm> converts a heap profile as produced
 629     by the <Option>-h&lt;break-down&gt;</Option> runtime option into a
 630     PostScript graph of the heap profile. By convention, the file to
 631     be processed by <command>hp2ps</command> has a
 632     <filename>.hp</filename> extension. The PostScript output is
 633     written to <filename>&lt;file&gt;@.ps</filename>. If
 634     <filename>&lt;file&gt;</filename> is omitted entirely, then the
 635     program behaves as a filter.</para>
 636
 637     <para><command>hp2ps</command> is distributed in
 638     <filename>ghc/utils/hp2ps</filename> in a GHC source
 639     distribution. It was originally developed by Dave Wakeling as part
 640     of the HBC/LML heap profiler.</para>
 641
 642     <para>The flags are:</para>
 643
 644     <variableList>
 645
 646       <varListEntry>
 647         <term><Option>-d</Option></Term>
 648         <listItem>
 649           <para>In order to make graphs more readable,
 650           <command>hp2ps</command> sorts the shaded bands for each
 651           identifier. The default sort ordering is for the bands with
 652           the largest area to be stacked on top of the smaller ones.
 653           The <Option>-d</Option> option causes rougher bands (those
 654           representing series of values with the largest standard
 655           deviations) to be stacked on top of smoother ones.</para>
 656         </listItem>
 657       </varListEntry>
 658
 659       <varListEntry>
 660         <term><Option>-b</Option></Term>
 661         <listItem>
 662           <para>Normally, <command>hp2ps</command> puts the title of
 663           the graph in a small box at the top of the page. However, if
 664           the JOB string is too long to fit in a small box (more than
 665           35 characters), then <command>hp2ps</command> will choose to
 666           use a big box instead.  The <Option>-b</Option> option
 667           forces <command>hp2ps</command> to use a big box.</para>
 668         </listItem>
 669       </varListEntry>
 670
 671       <varListEntry>
 672         <term><Option>-e&lt;float&gt;[in&verbar;mm&verbar;pt]</Option></Term>
 673         <listItem>
 674           <para>Generate encapsulated PostScript suitable for
 675           inclusion in LaTeX documents.  Usually, the PostScript graph
 676           is drawn in landscape mode in an area 9 inches wide by 6
 677           inches high, and <command>hp2ps</command> arranges for this
 678           area to be approximately centred on a sheet of a4 paper.
 679           This format is convenient of studying the graph in detail,
 680           but it is unsuitable for inclusion in LaTeX documents.  The
 681           <Option>-e</Option> option causes the graph to be drawn in
 682           portrait mode, with float specifying the width in inches,
 683           millimetres or points (the default).  The resulting
 684           PostScript file conforms to the Encapsulated PostScript
 685           (EPS) convention, and it can be included in a LaTeX document
 686           using Rokicki's dvi-to-PostScript converter
 687           <command>dvips</command>.</para>
 688         </listItem>
 689       </varListEntry>
 690
 691       <varListEntry>
 692         <term><Option>-g</Option></Term>
 693         <listItem>
 694           <para>Create output suitable for the <command>gs</command>
 695           PostScript previewer (or similar). In this case the graph is
 696           printed in portrait mode without scaling. The output is
 697           unsuitable for a laser printer.</para>
 698         </listItem>
 699       </varListEntry>
 700
 701       <varListEntry>
 702         <term><Option>-l</Option></Term>
 703         <listItem>
 704           <para>Normally a profile is limited to 20 bands with
 705           additional identifiers being grouped into an
 706           <literal>OTHER</literal> band. The <Option>-l</Option> flag
 707           removes this 20 band and limit, producing as many bands as
 708           necessary. No key is produced as it won't fit!. It is useful
 709           for creation time profiles with many bands.</para>
 710         </listItem>
 711       </varListEntry>
 712
 713       <varListEntry>
 714         <term><Option>-m&lt;int&gt;</Option></Term>
 715         <listItem>
 716           <para>Normally a profile is limited to 20 bands with
 717           additional identifiers being grouped into an
 718           <literal>OTHER</literal> band. The <Option>-m</Option> flag
 719           specifies an alternative band limit (the maximum is
 720           20).</para>
 721
 722           <para><Option>-m0</Option> requests the band limit to be
 723           removed. As many bands as necessary are produced. However no
 724           key is produced as it won't fit! It is useful for displaying
 725           creation time profiles with many bands.</para>
 726         </listItem>
 727       </varListEntry>
 728
 729       <varListEntry>
 730         <term><Option>-p</Option></Term>
 731         <listItem>
 732           <para>Use previous parameters. By default, the PostScript
 733           graph is automatically scaled both horizontally and
 734           vertically so that it fills the page.  However, when
 735           preparing a series of graphs for use in a presentation, it
 736           is often useful to draw a new graph using the same scale,
 737           shading and ordering as a previous one. The
 738           <Option>-p</Option> flag causes the graph to be drawn using
 739           the parameters determined by a previous run of
 740           <command>hp2ps</command> on <filename>file</filename>. These
 741           are extracted from <filename>file@.aux</filename>.</para>
 742         </listItem>
 743       </varListEntry>
 744
 745       <varListEntry>
 746         <term><Option>-s</Option></Term>
 747         <listItem>
 748           <para>Use a small box for the title.</para>
 749         </listItem>
 750       </varListEntry>
 751
 752       <varListEntry>
 753         <term><Option>-t&lt;float&gt;</Option></Term>
 754         <listItem>
 755           <para>Normally trace elements which sum to a total of less
 756           than 1&percnt; of the profile are removed from the
 757           profile. The <option>-t</option> option allows this
 758           percentage to be modified (maximum 5&percnt;).</para>
 759
 760           <para><Option>-t0</Option> requests no trace elements to be
 761           removed from the profile, ensuring that all the data will be
 762           displayed.</para>
 763         </listItem>
 764       </varListEntry>
 765
 766       <varListEntry>
 767         <term><Option>-c</Option></Term>
 768         <listItem>
 769           <para>Generate colour output.</para>
 770         </listItem>
 771       </varListEntry>
 772
 773       <varListEntry>
 774         <term><Option>-y</Option></Term>
 775         <listItem>
 776           <para>Ignore marks.</para>
 777         </listItem>
 778       </varListEntry>
 779
 780       <varListEntry>
 781         <term><Option>-?</Option></Term>
 782         <listItem>
 783           <para>Print out usage information.</para>
 784         </listItem>
 785       </varListEntry>
 786     </variableList>
 787   </sect1>
 788
 789   <sect1 id="ticky-ticky">
 790     <title>Using &ldquo;ticky-ticky&rdquo; profiling (for implementors)</Title>
 791     <indexterm><primary>ticky-ticky profiling</primary></indexterm>
 792
 793     <para>(ToDo: document properly.)</para>
 794
 795     <para>It is possible to compile Glasgow Haskell programs so that
 796     they will count lots and lots of interesting things, e.g., number
 797     of updates, number of data constructors entered, etc., etc.  We
 798     call this &ldquo;ticky-ticky&rdquo;
 799     profiling,<indexterm><primary>ticky-ticky
 800     profiling</primary></indexterm> <indexterm><primary>profiling,
 801     ticky-ticky</primary></indexterm> because that's the sound a Sun4
 802     makes when it is running up all those counters
 803     (<Emphasis>slowly</Emphasis>).</para>
 804
 805     <para>Ticky-ticky profiling is mainly intended for implementors;
 806     it is quite separate from the main &ldquo;cost-centre&rdquo;
 807     profiling system, intended for all users everywhere.</para>
 808
 809     <para>To be able to use ticky-ticky profiling, you will need to
 810     have built appropriate libraries and things when you made the
 811     system.  See &ldquo;Customising what libraries to build,&rdquo; in
 812     the installation guide.</para>
 813
 814     <para>To get your compiled program to spit out the ticky-ticky
 815     numbers, use a <Option>-r</Option> RTS
 816     option<indexterm><primary>-r RTS option</primary></indexterm>.
 817     See <XRef LinkEnd="runtime-control">.</para>
 818
 819     <para>Compiling your program with the <Option>-ticky</Option>
 820     switch yields an executable that performs these counts.  Here is a
 821     sample ticky-ticky statistics file, generated by the invocation
 822     <command>foo +RTS -rfoo.ticky</command>.</para>
 823
 824 <screen>
 825  foo +RTS -rfoo.ticky
 826
 827
 828 ALLOCATIONS: 3964631 (11330900 words total: 3999476 admin, 6098829 goods, 1232595 slop)
 829                                 total words:        2     3     4     5    6+
 830   69647 (  1.8%) function values                 50.0  50.0   0.0   0.0   0.0
 831 2382937 ( 60.1%) thunks                           0.0  83.9  16.1   0.0   0.0
 832 1477218 ( 37.3%) data values                     66.8  33.2   0.0   0.0   0.0
 833       0 (  0.0%) big tuples
 834       2 (  0.0%) black holes                      0.0 100.0   0.0   0.0   0.0
 835       0 (  0.0%) prim things
 836   34825 (  0.9%) partial applications             0.0   0.0   0.0 100.0   0.0
 837       2 (  0.0%) thread state objects             0.0   0.0   0.0   0.0 100.0
 838
 839 Total storage-manager allocations: 3647137 (11882004 words)
 840         [551104 words lost to speculative heap-checks]
 841
 842 STACK USAGE:
 843
 844 ENTERS: 9400092  of which 2005772 (21.3%) direct to the entry code
 845                   [the rest indirected via Node's info ptr]
 846 1860318 ( 19.8%) thunks
 847 3733184 ( 39.7%) data values
 848 3149544 ( 33.5%) function values
 849                   [of which 1999880 (63.5%) bypassed arg-satisfaction chk]
 850  348140 (  3.7%) partial applications
 851  308906 (  3.3%) normal indirections
 852       0 (  0.0%) permanent indirections
 853
 854 RETURNS: 5870443
 855 2137257 ( 36.4%) from entering a new constructor
 856                   [the rest from entering an existing constructor]
 857 2349219 ( 40.0%) vectored [the rest unvectored]
 858
 859 RET_NEW:         2137257:  32.5% 46.2% 21.3%  0.0%  0.0%  0.0%  0.0%  0.0%  0.0%
 860 RET_OLD:         3733184:   2.8% 67.9% 29.3%  0.0%  0.0%  0.0%  0.0%  0.0%  0.0%
 861 RET_UNBOXED_TUP:       2:   0.0%  0.0%100.0%  0.0%  0.0%  0.0%  0.0%  0.0%  0.0%
 862
 863 RET_VEC_RETURN : 2349219:   0.0%  0.0%100.0%  0.0%  0.0%  0.0%  0.0%  0.0%  0.0%
 864
 865 UPDATE FRAMES: 2241725 (0 omitted from thunks)
 866 SEQ FRAMES:    1
 867 CATCH FRAMES:  1
 868 UPDATES: 2241725
 869       0 (  0.0%) data values
 870   34827 (  1.6%) partial applications
 871                   [2 in place, 34825 allocated new space]
 872 2206898 ( 98.4%) updates to existing heap objects (46 by squeezing)
 873 UPD_CON_IN_NEW:         0:       0      0      0      0      0      0      0      0      0
 874 UPD_PAP_IN_NEW:     34825:       0      0      0  34825      0      0      0      0      0
 875
 876 NEW GEN UPDATES: 2274700 ( 99.9%)
 877
 878 OLD GEN UPDATES: 1852 (  0.1%)
 879
 880 Total bytes copied during GC: 190096
 881
 882 **************************************************
 883 3647137 ALLOC_HEAP_ctr
 884 11882004 ALLOC_HEAP_tot
 885   69647 ALLOC_FUN_ctr
 886   69647 ALLOC_FUN_adm
 887   69644 ALLOC_FUN_gds
 888   34819 ALLOC_FUN_slp
 889   34831 ALLOC_FUN_hst_0
 890   34816 ALLOC_FUN_hst_1
 891       0 ALLOC_FUN_hst_2
 892       0 ALLOC_FUN_hst_3
 893       0 ALLOC_FUN_hst_4
 894 2382937 ALLOC_UP_THK_ctr
 895       0 ALLOC_SE_THK_ctr
 896  308906 ENT_IND_ctr
 897       0 E!NT_PERM_IND_ctr requires +RTS -Z
 898 [... lots more info omitted ...]
 899       0 GC_SEL_ABANDONED_ctr
 900       0 GC_SEL_MINOR_ctr
 901       0 GC_SEL_MAJOR_ctr
 902       0 GC_FAILED_PROMOTION_ctr
 903   47524 GC_WORDS_COPIED_ctr
 904 </screen>
 905
 906     <para>The formatting of the information above the row of asterisks
 907     is subject to change, but hopefully provides a useful
 908     human-readable summary.  Below the asterisks <Emphasis>all
 909     counters</Emphasis> maintained by the ticky-ticky system are
 910     dumped, in a format intended to be machine-readable: zero or more
 911     spaces, an integer, a space, the counter name, and a newline.</para>
 912
 913     <para>In fact, not <Emphasis>all</Emphasis> counters are
 914     necessarily dumped; compile- or run-time flags can render certain
 915     counters invalid.  In this case, either the counter will simply
 916     not appear, or it will appear with a modified counter name,
 917     possibly along with an explanation for the omission (notice
 918     <literal>ENT&lowbar;PERM&lowbar;IND&lowbar;ctr</literal> appears
 919     with an inserted <literal>!</literal> above).  Software analysing
 920     this output should always check that it has the counters it
 921     expects.  Also, beware: some of the counters can have
 922     <Emphasis>large</Emphasis> values!</para>
 923
 924   </sect1>
 925
 926 </chapter>
 927
 928 <!-- Emacs stuff:
 929      ;;; Local Variables: ***
 930      ;;; mode: sgml ***
 931      ;;; sgml-parent-document: ("users_guide.sgml" "book" "chapter") ***
 932      ;;; End: ***
 933  -->