lib/pan/doc/HOWTO.html

   1 <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML//EN">
   2 <html> <head>
   3 <title>pan HOWTO</title>
   4 </head>
   5
   6 <body>
   7 <h1>pan HOWTO</h1>
   8 <h2>intro</h2>
   9   pan was developed to solve this common problem; what resources (CPU
  10 time and memory consumption) does a set of actions (a test case)
  11 consume? the basic idea is that you start the measurement, perform the
  12 test case and stop the measurement. this will generate a set of data
  13 files containing a wealth of information, which can then be processed
  14 to present e.g.
  15 <ul>
  16   <li>how much CPU time and memory each erlang process consumed
  17   <li>how much memory was added to each ets table
  18   <li>what did the call stack look like when some function was called
  19   <li>what messages were sent between processes
  20 </ul>
  21 at the current stage the program is similar in functionality to the OTP
  22 applications <code>dbg</code> and <code>eprof</code>, and the unix
  23 application <code>top</code>, as well as some extras. it is designed to run
  24 with minimal impact (which is sometimes huge) in an embedded
  25 environment. <p>
  26 alas, it is not a product, so your mileage will vary.
  27
  28 <hr>
  29 <h2>basic</h2>
  30 pan should be run from an erlang node (the host). the host must be
  31 able to attach itself to the target, but should be hidden (<code>erl
  32 -hidden</code>).  when pan is started, it will load itself on the
  33 target(s), and start a tracing process.  the target process will
  34 generate a data file containing information about the
  35 operating system and the erlang emulator, as well as about the erlang
  36 processes and the erlang tables. when the target process(es) are
  37 terminated the data files will be moved to the host.
  38 <p>
  39   the data files are stored in a file tree that uses the name of the
  40 test case, the name of the CP and the timestamp to generate unique
  41 names. they can be analyzed in different fashions.
  42
  43 <hr>
  44 <h2>data taking</h2>
  45 <h3>pan:start/stop</h3>
  46 <code>pan:start(Tc,Nodes,Procs,Flags,MatchSpecs).</code>
  47 <p>
  48 <code>pan:stop()</code>
  49 <p>
  50   see the <a href="pan.html">reference</a> for a detailed description
  51 of the parameters. briefly; <code>Tc</code> (test case) is a tag used
  52 to label the data files, <code>Nodes</code> is a list of target nodes
  53 to run on, <code>Procs</code> is a list of processes to trace on,
  54 <code>Flags</code> is a list of tracing flags and Matches is a list of
  55 match specifications (see erlang tracing documentation
  56 <a href="http://www.erlang.org/doc/r9b/lib/kernel-2.8.0/doc/html/erlang.html#trace_3">(R9)</a>
  57 <a href="http://www.erlang.org/doc/r8b/lib/kernel-2.7.3/doc/html/erlang.html#trace_3">(R8)</a>
  58 <a href="http://www.erlang.org/doc/r7b/lib/kernel-2.6.2/doc/html/erlang.html#trace_3">(R7)</a>).
  59 (if the parameters are not given as lists they will be treated as
  60 lists of length 1).
  61 <p>
  62 <code>Tc</code> can be the special atom <code>ip</code>, which means that the
  63 tracing info will display on the host terminal instead of being sent to file.
  64 <p>
  65   for the casual user the <code>Flags</code> parameter is typically either the
  66 <code>prof</code> or <code>perf</code> aliases or, for the expert, a list of
  67 trace flags. the resulting files are typically analyzed with the functions
  68 <code>pan:prof</code>, <code>pan:perf</code> or <code>pan:scan</code>,
  69 respectively.
  70
  71
  72 <hr>
  73 <h2>analysis</h2>
  74 <h3>pan:perf</h3>
  75 the pan:perf function provide information about;
  76 <ul>
  77   <li>the os environment, things like context switches,
  78       interrupts, system calls etc (see the <code>mpstat</code>
  79       man page for details)
  80       <pre>
  81 ###############################################################################
  82 CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
  83 0    0   0    0   308  107  335   59    0   34    0   649    1   1   0  98
  84 0  166   0    0   399  189  509   92    0   36    0  3699   19   7   1  73
  85       </pre>
  86   <li>the ets/dets tables, changes in size (number of object) and
  87       memory (number of bytes)
  88       <pre>
  89 ###############################################################################
  90 type id           name                             size   diff mem_Byte    diff
  91 Change ========================================================================
  92 ets  x            ftmIfpMap                        2025    743   198392   72496
  93 ets  292          mnesia_index                     2025    743   190292   69524
  94 ets  x            prmMib                           1382    319   231900   55024
  95 ets  365          snmp_index                        828    378    99416   45360
  96 </pre>
  97
  98   <li>erlang processes, the number of microseconds used by each
  99       process.<br>
 100
 101       in this case <code>pan</code> has generated a file using the command
 102       <code>pan:start(migOm,'axd301@cp1-19','',perf)</code>
 103       running <code>pan:perf("/tmp/pan/migOm")</code> we'll see the erlang
 104       processes sorted after how much cpu time they consumed
 105       (<code>cpu</code>). the <code>pid</code> is replaced by a count
 106       if there were more than one process with that <code>id</code>. the
 107       <code>id</code> is the registered name or, lacking that, the initial
 108       call. some initial calls are recognized and mangled to be more useful.
 109       <code>gc</code>is the number of garbage collects on the process, and
 110       <code>in</code> is the number of times the process was scheduled to run.
 111 <pre>
 112 pan: /tmp/pan/migOm/axd301@cp1-19
 113 pid           id                                            gc     in       cpu
 114 ===============================================================================
 115 <122.5440.0>  dpComServer                                   73    849    548900
 116 <122.5574.0>  plcMemory                                      0    170    192779
 117 <122.5435.0>  cpmServer                                      7     58    119229
 118 <122.5569.0>  sbm                                            3     69     68211
 119 38            {sysTimer,do_apply_after,5}                    0     75     13055
 120 5             {inet_tcp_dist,do_accept,6}                   10     39     11257
 121 2             {pthTcpNetHandler,init,1}                      8     36      8757
 122 <122.6819.0>  pthTcpCh2                                     16     28      8296
 123 <122.6229.0>  {jive_broker,init,2}                           5     15      7948
 124 <122.6818.0>  pthTcpOm1                                     16     27      7494
 125 <122.6778.0>  pthOm                                          6     31      7431
 126 2             {sysTimer,do_apply_interval,6}                 4     16      4083
 127 <122.6781.0>  pthOmTimer                                     1     22      2784
 128 <122.17.0>    net_kernel                                     0      7      1697
 129 <122.10.0>    rex                                            1      6      1037
 130 </pre>
 131 </ul>
 132 <h3>pan:prof</h3>
 133   <code>pan:prof</code> implements a profiler, i.e. a tool that shows cpu usage
 134 per function. in this example the data was taken using the command
 135 <code>pan:start(tst,'axd301@cp1-19','',prof,{'_',local})</code>
 136
 137   <code>pan:prof/1</code> shows the cpu usage per process (similar to
 138 <code>pan:perf</code>).
 139
 140 <pre>
 141 > pan:prof("/tmp/pan/tst").
 142 cb_eprof:28: end of trace
 143 all; N = 29, 1127459 us 1127459 us/proc (100.0000)
 144   process tag                                                    procs    cpu%
 145   dpComServer.................................................     1.0    53.7
 146   plcMemory...................................................     1.0    17.1
 147   cpmServer...................................................     1.0    11.7
 148   sbm.........................................................     1.0     6.1
 149 </pre>
 150
 151 <code>pan:prof/2</code> shows the cpu usage per function for a process
 152 (in this case plcMemory).
 153 <pre>
 154 > pan:prof("/tmp/pan/tst",plcMemory).
 155 plcMemory; N = 1, 192779 us 192779 us/proc (100.000)
 156   MFA                                                            calls    cpu%
 157   {ets,local_info,3}..........................................  2430.0    30.2
 158   {ets,db_info,2}.............................................  2430.0    27.6
 159   {plcMemory,do_calculate,6}..................................     1.0    24.6
 160   {ets,info,2}................................................  2430.0    14.7
 161   {ets,all,0}.................................................     1.0     1.7
 162   {ets,insert,2}..............................................    32.0     0.4
 163   {ets,lookup,2}..............................................    30.0     0.3
 164 </pre>
 165
 166 <code>pan:prof/3</code> shows the cpu usage per function for a given
 167 process and stack.
 168 <pre>
 169 > pan:prof("/tmp/pan/tst",plcMemory,[{plcMemory,check_loop,5},{timer,tc,3},{plcMemory,calculate,3},{plcMemory,do_calculate,6}]).
 170 MFA                                                            calls       cpu%
 171 {plcMemory,check_loop,5}.....................................      0       0.0%
 172 {timer,tc,3}.................................................      1       0.0%
 173 {plcMemory,calculate,3}......................................      1       0.0%
 174 {plcMemory,do_calculate,6}...................................      1      24.6%
 175    , {ets,info,2}............................................   2430      72.6%
 176    , {ets,insert,2}..........................................     30       0.4%
 177    , {ets,lookup,2}..........................................     30       0.3%
 178    , {ets,delete,1}..........................................      1       0.1%
 179    , {ets,rename,2}..........................................      1       0.0%
 180    , {ets,new,2}.............................................      1       0.0%
 181 total                                                                     98.0%
 182 </pre>
 183
 184 the special case where the stack is the empty atom <code>''</code> finds the
 185 most expensive stack;
 186 <pre>
 187 > pan:prof("/tmp/pan/tst",plcMemory,'').
 188 MFA                                                            calls       cpu%
 189 {plcMemory,check_loop,5}.....................................      0       0.0%
 190 {timer,tc,3}.................................................      1       0.0%
 191 {plcMemory,calculate,3}......................................      1       0.0%
 192 {plcMemory,do_calculate,6}...................................      1      24.6%
 193 {ets,info,2}.................................................   2430      14.7%
 194 {ets,local_info,3}...........................................   2430      30.2%
 195 {ets,db_info,2}..............................................   2430      27.6%
 196 total                                                                     97.3%
 197 </pre>
 198 <h3>pan:scan</h3>
 199 scans the contents of a trace file, filters each trace message and (optionally)
 200 prints it.the filter can be either a (list of) term(s), in which case the
 201 trace message is printed if it contains the term(s), or a callback function.
 202 the callback function can do anything it wants with the messages.
 203 <p>
 204 <ul>
 205   <li><code>pan:scan("foo",'',bla)</code> prints all trace messages from the
 206       file "foo" that contains the atom 'bla' to the screen
 207   <li><code>pan:scan("foo","aik",losers,0,100)</code> prints all trace
 208       messages out of the first 100 from the file "foo" that contains the
 209       atom 'losers' to the file "aik"
 210 </ul>
 211 <hr>
 212 <h2>debugging</h2>
 213 <h3>pan:dbg</h3> provides functionality similar to the OTP
 214 application <code>dbg</code>.
 215 <ul>
 216   <li><code>pan:dbg(start,["^mdisp",ccLib],'axd301@cp1-1')</code> shows all
 217       calls to functions in ccLib or in modules that starts with 'mdisp' on
 218       the node 'axd301@cp1-1'.
 219 </ul>
 220 <hr>
 221 the <a href="pan.html">reference</a>
 222 <hr>
 223 <h3>installation</h3>
 224 available via anonymous cvs from www.sourceforge.net/projects/jungerl
 225 (cvsroot pserver:anonymous@cvs.sourceforge.net:/cvsroot/jungerl)
 226 or the sourceforge tarballs
 227 http://cvs.sourceforge.net/cvstarballs/jungerl-cvsroot.tar.gz
 228 <hr>
 229 <address>mats.cronqvist@ericsson.com</address>
 230 <!-- hhmts start -->
 231 Last modified: Wed Mar 26 11:29:40 MET 2003
 232 <!-- hhmts end -->
 233 </body> </html>