PageRenderTime 18ms CodeModel.GetById 7ms app.highlight 5ms RepoModel.GetById 1ms app.codeStats 0ms

/lib/pan/doc/HOWTO.html

https://github.com/gebi/jungerl
HTML | 233 lines | 219 code | 12 blank | 2 comment | 0 complexity | 3ac26568e547d4155740aa0e209769f4 MD5 | raw file
  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
 10time and memory consumption) does a set of actions (a test case)
 11consume? the basic idea is that you start the measurement, perform the
 12test case and stop the measurement. this will generate a set of data
 13files containing a wealth of information, which can then be processed
 14to 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>
 21at the current stage the program is similar in functionality to the OTP
 22applications <code>dbg</code> and <code>eprof</code>, and the unix
 23application <code>top</code>, as well as some extras. it is designed to run
 24with minimal impact (which is sometimes huge) in an embedded
 25environment. <p>
 26alas, it is not a product, so your mileage will vary.
 27
 28<hr>
 29<h2>basic</h2>
 30pan should be run from an erlang node (the host). the host must be
 31able 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
 33target(s), and start a tracing process.  the target process will
 34generate a data file containing information about the
 35operating system and the erlang emulator, as well as about the erlang
 36processes and the erlang tables. when the target process(es) are
 37terminated 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
 40test case, the name of the CP and the timestamp to generate unique
 41names. 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
 51of the parameters. briefly; <code>Tc</code> (test case) is a tag used
 52to label the data files, <code>Nodes</code> is a list of target nodes
 53to 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
 55match 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
 60lists of length 1).
 61<p>
 62<code>Tc</code> can be the special atom <code>ip</code>, which means that the
 63tracing 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
 67trace flags. the resulting files are typically analyzed with the functions
 68<code>pan:prof</code>, <code>pan:perf</code> or <code>pan:scan</code>,
 69respectively.
 70
 71
 72<hr>
 73<h2>analysis</h2>
 74<h3>pan:perf</h3>
 75the 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###############################################################################
 82CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
 830    0   0    0   308  107  335   59    0   34    0   649    1   1   0  98
 840  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###############################################################################
 90type id           name                             size   diff mem_Byte    diff
 91Change ========================================================================
 92ets  x            ftmIfpMap                        2025    743   198392   72496
 93ets  292          mnesia_index                     2025    743   190292   69524
 94ets  x            prmMib                           1382    319   231900   55024
 95ets  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>
112pan: /tmp/pan/migOm/axd301@cp1-19
113pid           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
11938            {sysTimer,do_apply_after,5}                    0     75     13055
1205             {inet_tcp_dist,do_accept,6}                   10     39     11257
1212             {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
1262             {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
134per 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").                          
142cb_eprof:28: end of trace
143all; 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).
155plcMemory; 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
167process 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}]).
170MFA                                                            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%
181total                                                                     98.0%
182</pre>
183
184the special case where the stack is the empty atom <code>''</code> finds the
185most expensive stack;
186<pre>
187> pan:prof("/tmp/pan/tst",plcMemory,'').
188MFA                                                            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%
196total                                                                     97.3%
197</pre>
198<h3>pan:scan</h3>
199scans the contents of a trace file, filters each trace message and (optionally)
200prints it.the filter can be either a (list of) term(s), in which case the
201trace message is printed if it contains the term(s), or a callback function.
202the 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
214application <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>
221the <a href="pan.html">reference</a>
222<hr>
223<h3>installation</h3>
224available via anonymous cvs from www.sourceforge.net/projects/jungerl
225(cvsroot pserver:anonymous@cvs.sourceforge.net:/cvsroot/jungerl)
226or the sourceforge tarballs
227http://cvs.sourceforge.net/cvstarballs/jungerl-cvsroot.tar.gz
228<hr>
229<address>mats.cronqvist@ericsson.com</address>
230<!-- hhmts start -->
231Last modified: Wed Mar 26 11:29:40 MET 2003
232<!-- hhmts end -->
233</body> </html>