PageRenderTime 54ms CodeModel.GetById 23ms RepoModel.GetById 0ms app.codeStats 0ms

/lib/pan/doc/HOWTO.html

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