dbg
and eprof
, and the unix
application top
, as well as some extras. it is designed to run
with minimal impact (which is sometimes huge) in an embedded
environment. alas, it is not a product, so your mileage will vary.
erl
-hidden
). when pan is started, it will load itself on the
target(s), and start a tracing process. the target process will
generate a data file containing information about the
operating system and the erlang emulator, as well as about the erlang
processes and the erlang tables. when the target process(es) are
terminated the data files will be moved to the host.
the data files are stored in a file tree that uses the name of the test case, the name of the CP and the timestamp to generate unique names. they can be analyzed in different fashions.
pan:start(Tc,Nodes,Procs,Flags,MatchSpecs).
pan:stop()
see the reference for a detailed description
of the parameters. briefly; Tc
(test case) is a tag used
to label the data files, Nodes
is a list of target nodes
to run on, Procs
is a list of processes to trace on,
Flags
is a list of tracing flags and Matches is a list of
match specifications (see erlang tracing documentation
(R9)
(R8)
(R7)).
(if the parameters are not given as lists they will be treated as
lists of length 1).
Tc
can be the special atom ip
, which means that the
tracing info will display on the host terminal instead of being sent to file.
for the casual user the Flags
parameter is typically either the
prof
or perf
aliases or, for the expert, a list of
trace flags. the resulting files are typically analyzed with the functions
pan:prof
, pan:perf
or pan:scan
,
respectively.
mpstat
man page for details)
############################################################################### CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl 0 0 0 0 308 107 335 59 0 34 0 649 1 1 0 98 0 166 0 0 399 189 509 92 0 36 0 3699 19 7 1 73
############################################################################### type id name size diff mem_Byte diff Change ======================================================================== ets x ftmIfpMap 2025 743 198392 72496 ets 292 mnesia_index 2025 743 190292 69524 ets x prmMib 1382 319 231900 55024 ets 365 snmp_index 828 378 99416 45360
pan
has generated a file using the command
pan:start(migOm,'axd301@cp1-19','',perf)
running pan:perf("/tmp/pan/migOm")
we'll see the erlang
processes sorted after how much cpu time they consumed
(cpu
). the pid
is replaced by a count
if there were more than one process with that id
. the
id
is the registered name or, lacking that, the initial
call. some initial calls are recognized and mangled to be more useful.
gc
is the number of garbage collects on the process, and
in
is the number of times the process was scheduled to run.
pan: /tmp/pan/migOm/axd301@cp1-19 pid id gc in cpu =============================================================================== <122.5440.0> dpComServer 73 849 548900 <122.5574.0> plcMemory 0 170 192779 <122.5435.0> cpmServer 7 58 119229 <122.5569.0> sbm 3 69 68211 38 {sysTimer,do_apply_after,5} 0 75 13055 5 {inet_tcp_dist,do_accept,6} 10 39 11257 2 {pthTcpNetHandler,init,1} 8 36 8757 <122.6819.0> pthTcpCh2 16 28 8296 <122.6229.0> {jive_broker,init,2} 5 15 7948 <122.6818.0> pthTcpOm1 16 27 7494 <122.6778.0> pthOm 6 31 7431 2 {sysTimer,do_apply_interval,6} 4 16 4083 <122.6781.0> pthOmTimer 1 22 2784 <122.17.0> net_kernel 0 7 1697 <122.10.0> rex 1 6 1037
pan:prof
implements a profiler, i.e. a tool that shows cpu usage
per function. in this example the data was taken using the command
pan:start(tst,'axd301@cp1-19','',prof,{'_',local})
pan:prof/1
shows the cpu usage per process (similar to
pan:perf
).
> pan:prof("/tmp/pan/tst"). cb_eprof:28: end of trace all; N = 29, 1127459 us 1127459 us/proc (100.0000) process tag procs cpu% dpComServer................................................. 1.0 53.7 plcMemory................................................... 1.0 17.1 cpmServer................................................... 1.0 11.7 sbm......................................................... 1.0 6.1
pan:prof/2
shows the cpu usage per function for a process
(in this case plcMemory).
> pan:prof("/tmp/pan/tst",plcMemory). plcMemory; N = 1, 192779 us 192779 us/proc (100.000) MFA calls cpu% {ets,local_info,3}.......................................... 2430.0 30.2 {ets,db_info,2}............................................. 2430.0 27.6 {plcMemory,do_calculate,6}.................................. 1.0 24.6 {ets,info,2}................................................ 2430.0 14.7 {ets,all,0}................................................. 1.0 1.7 {ets,insert,2}.............................................. 32.0 0.4 {ets,lookup,2}.............................................. 30.0 0.3
pan:prof/3
shows the cpu usage per function for a given
process and stack.
> pan:prof("/tmp/pan/tst",plcMemory,[{plcMemory,check_loop,5},{timer,tc,3},{plcMemory,calculate,3},{plcMemory,do_calculate,6}]). MFA calls cpu% {plcMemory,check_loop,5}..................................... 0 0.0% {timer,tc,3}................................................. 1 0.0% {plcMemory,calculate,3}...................................... 1 0.0% {plcMemory,do_calculate,6}................................... 1 24.6% , {ets,info,2}............................................ 2430 72.6% , {ets,insert,2}.......................................... 30 0.4% , {ets,lookup,2}.......................................... 30 0.3% , {ets,delete,1}.......................................... 1 0.1% , {ets,rename,2}.......................................... 1 0.0% , {ets,new,2}............................................. 1 0.0% total 98.0%the special case where the stack is the empty atom
''
finds the
most expensive stack;
> pan:prof("/tmp/pan/tst",plcMemory,''). MFA calls cpu% {plcMemory,check_loop,5}..................................... 0 0.0% {timer,tc,3}................................................. 1 0.0% {plcMemory,calculate,3}...................................... 1 0.0% {plcMemory,do_calculate,6}................................... 1 24.6% {ets,info,2}................................................. 2430 14.7% {ets,local_info,3}........................................... 2430 30.2% {ets,db_info,2}.............................................. 2430 27.6% total 97.3%
pan:scan("foo",'',bla)
prints all trace messages from the
file "foo" that contains the atom 'bla' to the screen
pan:scan("foo","aik",losers,0,100)
prints all trace
messages out of the first 100 from the file "foo" that contains the
atom 'losers' to the file "aik"
dbg
.
pan:dbg(start,["^mdisp",ccLib],'axd301@cp1-1')
shows all
calls to functions in ccLib or in modules that starts with 'mdisp' on
the node 'axd301@cp1-1'.