The Trace Tool Builder is a base for building trace tools for
single node or distributed erlang systems. It requires the
runtime_tools
application to be available on the traced
node.
The main features of the Trace Tool Builder are:
Even though the intention of the Trace Tool Builder is to serve
as a base for tailor made trace tools, it is of course possible
to use it directly from the erlang shell. The application only
allows the use of file port tracer, so if you would like would
like to use other types of trace clients you will be better off
using dbg
directly instead.
The ttb
module is the interface to all functions in the
Trace Tool Builder. To get started the least you need to do is to
start a tracer with ttb:tracer/0/1/2
, and set the required
trace flags on the processes you want to trace with
ttb:p/2
. Then, when the tracing is completed, you must stop
the tracer with ttb:stop/0/1
and format the trace log with
ttb:format/1/2
.
ttb:tracer/0/1/2
opens a file trace port on each node
that shall be traced. All trace messages will be written to this
port and end up in a binary file (the binary trace log).
ttb:p/2
specifies which processes that shall be
traced. Trace flags given in this call specifies what to trace on
each process. You can call this function several times if you like
different trace flags to be set on different processes.
If you want to trace function calls (i.e. if you have the
call
trace flag set on any of your processes), you must
also set trace patterns on the required function(s) with
ttb:tp
or ttb:tpl
. A function is only traced if it
has a trace pattern. The trace pattern specifies how to trace the
function by using match specifications. Match specifications are
described in the User's Guide for the erlang runtime system
erts
.
ttb:stop/0/1
stops tracing on all nodes, deletes all
trace patterns and flushes the trace port buffer.
ttb:format/1/2
translates the binary trace logs into
something readable. By default ttb
presents each trace
message as a line of text, but you can also write your own handler
to make more complex interpretations of the trace information. A
trace log can even be presented graphically via the Event Tracer
application. Note that if you give the format
option to
ttb:stop/1
the formatting is automatically done when
stopping ttb
.
This small module is used in the example:
-module(m). -export([f/0]). f() -> receive From when pid(From) -> Now = erlang:now(), From ! {self(),Now} end.
The following example shows the basic use of ttb
from
the erlang shell. Default options are used both for starting the
tracer and for formatting. This gives a trace log named
Node-ttb
, where Node
is the name of the node. The
default handler prints the formatted trace messages in the
shell.
(tiger@durin)47> %% First I spawn a process running my test function (tiger@durin)47> Pid = spawn(m,f,[]). <0.125.0> (tiger@durin)48> (tiger@durin)48> %% Then I start a tracer... (tiger@durin)48> ttb:tracer(). {ok,[tiger@durin]} (tiger@durin)49> (tiger@durin)49> %% and activate the new process for tracing (tiger@durin)49> %% function calls and sent messages. (tiger@durin)49> ttb:p(Pid,[call,send]). {ok,[{<0.125.0>,[{matched,tiger@durin,1}]}]} (tiger@durin)50> (tiger@durin)50> %% Here I set a trace pattern on erlang:now/0 (tiger@durin)50> %% The trace pattern is a simple match spec (tiger@durin)50> %% generated by dbg:fun2ms/1. It indicates that (tiger@durin)50> %% the return value shall be traced. (tiger@durin)50> MS = dbg:fun2ms(fun(_) -> return_trace() end). [{'_',[],[{return_trace}]}] (tiger@durin)51> ttb:tp(erlang,now,MS). {ok,[{matched,tiger@durin,1},{saved,1}]} (tiger@durin)52> (tiger@durin)52> %% I run my test (i.e. send a message to (tiger@durin)52> %% my new process) (tiger@durin)52> Pid ! self(). <0.72.0> (tiger@durin)53> (tiger@durin)53> %% And then I have to stop ttb in order to flush (tiger@durin)53> %% the trace port buffer (tiger@durin)53> ttb:stop(). stopped (tiger@durin)54> (tiger@durin)54> %% Finally I format my trace log (tiger@durin)54> ttb:format("tiger@durin-ttb"). ({<0.125.0>,{m,f,0},tiger@durin}) call erlang:now() ({<0.125.0>,{m,f,0},tiger@durin}) returned from erlang:now/0 -> {1031,133451,667611} ({<0.125.0>,{m,f,0},tiger@durin}) <0.72.0> ! {<0.125.0>,{1031,133451,667611}} ok
This small example shows a simple tool for "debug tracing", i.e. tracing of function calls with return values.
-module(mydebug). -export([start/0,trc/1,stop/0,format/1]). -export([print/4]). %% Include ms_transform.hrl so that I can use dbg:fun2ms/2 to %% generate match specifications. -include_lib("stdlib/include/ms_transform.hrl"). %%% -------------Tool API------------- %%% ---------------------------------- %%% Star the "mydebug" tool start() -> %% The options specify that the binary log shall be named %% <Node>-debug_log and that the print/4 function in this %% module shall be used as format handler ttb:tracer(all,[{file,"debug_log"},{handler,{{?MODULE,print},0}}]), %% All processes (existing and new) shall trace function calls %% and include a timestamp in each trace message ttb:p(all,[call,timestamp]). %%% Set trace pattern on function(s) trc(M) when atom(M) -> trc({M,'_','_'}); trc({M,F}) when atom(M), atom(F) -> trc({M,F,'_'}); trc({M,F,_A}=MFA) when atom(M), atom(F) -> %% This match spec specifies that return values shall %% be traced. NOTE that ms_transform.hrl must be included %% if dbg:fun2ms/1 shall be used! MatchSpec = dbg:fun2ms(fun(_) -> return_trace() end), ttb:tpl(MFA,MatchSpec). %%% Format a binary trace log format(File) -> ttb:format(File). %%% Stop the "mydebug" tool stop() -> ttb:stop(). %%% --------Internal functions-------- %%% ---------------------------------- %%% Format handler print(_Out,end_of_trace,_TI,N) -> N; print(Out,Trace,_TI,N) -> do_print(Out,Trace,N), N+1. do_print(Out,{trace_ts,P,call,{M,F,A},Ts},N) -> io:format(Out, "~w: ~w, ~w:~n" "Call : ~w:~w/~w~n" "Arguments :~p~n~n", [N,Ts,P,M,F,length(A),A]); do_print(Out,{trace_ts,P,return_from,{M,F,A},R,Ts},N) -> io:format(Out, "~w: ~w, ~w:~n" "Return from : ~w:~w/~w~n" "Return value :~p~n~n", [N,Ts,P,M,F,A,R]).
To distinguish trace logs produced with this tool from other
logs, the file
option is used in tracer/2
. The
logs will therefore be named Node-debug_log
, where
Node
is the name of the node where the log is produced.
By using the handler
option when starting the tracer,
the information about how to format the file is stored in the
trace information file (.ti
). This is not necessary, as
it might be given at the time of formatting instead. It can
however be useful if you e.g. want to automatically format your
trace logs by using the format
option in
ttb:stop/1
. It also means that you don't need any
knowledge of the content of a binary log to be able to format it
the way it was intended. If the handler
option is given
both when starting the tracer and when formatting, the one given
when formatting is used.
The call
trace flag is set on all processes. This
means that any function activated with the trc/1
command
will be traced on all existing and new processes.
The Observer application might not always be available on the node that shall be traced (in the following called the "traced node"). It is still possible to run the Trace Tool Builder from another node (in the following called the "trace control node") as long as
If the Trace Tool Builder shall be used against a remote node,
it is highly recommended to start the trace control node as
hidden. This way it can connect to the traced node
without the traced node "seeing" it, i.e. if the nodes()
BIF is called on the traced node, the trace control node will not
show. To start a hidden node, add the -hidden
option to the
erl
command, e.g.
% erl -sname trace_control -hidden
If the traced node is diskless, ttb
must be started from
a trace control node with disk access, and the file
option
must be given to the tracer/2
function with the value
{local, File}
, e.g.
(trace_control@durin)1> ttb:tracer(mynode@diskless,[{file,{local, {wrap,"mytrace"}}}]). {ok,[mynode@diskless]}
In addition to the trace log file(s), a file with the extension
.ti
is created when the Trace Tool Builder is started. This
is the trace information file. It is a binary file, and it
contains the process information, trace flags used, the name of
the node to which it belongs and all information written with the
write_trace_info/2
function.
To be able to use all this information during formatting, it is
important that the trace information file exists in the same
directory as the trace log, and that it has the same name as the
trace log with the additional extension .ti
.
Except for the process information, everything in the trace
information file is passed on to the handler function when
formatting. The TI
parameter is a list of
{Key,ValueList}
tuples. The keys flags
,
handler
, file
and node
are used for
information written directly by ttb
.
You can add information to the trace information file by
calling write_trace_info/2
. Note that ValueList
always will be a list, and if you call write_trace_info/2
several times with the same Key
, the ValueList
will
be extended with a new value each time. Example:
ttb:write_trace_info(mykey,1)
gives the entry
{mykey,[1]}
in TI
. Another call,
ttb:write_trace_info(mykey,2)
, changes this entry to
{mykey,[1,2]}
.
If you want to limit the size of the trace logs, you can use
wrap logs. This works almost like a ciclular buffer. You can
specify the maximum number of binary logs and the maximum size of
each log. ttb
will create a new binary log each time a log
reaches the maximum size. When the the maximum number of logs are
reached, the oldest log is deleted before a new one is created.
Wrap logs can be formatted one by one or all at once. See Formatting.
Formatting can be done automatically when stopping ttb
(see Automatically collect and
format logs from all nodes), or explicitly by calling
the ttb:format/1/2
function.
Formatting means to read a binary log and present it in a
readable format. You can use the default format handler in
ttb
to present each trace message as a line of text, or
write your own handler to make more complex interpretations of the
trace information. You can even use the Event Tracer et
to
present the trace log graphically (see Presenting trace logs with Event
Tracer).
The first argument to ttb:format/1/2
specifies which
binary log(s) to format. This can be the name of one binary log, a
list of such logs or the name of a directory containing one or
more binary logs. If this argument indicates more than one log,
and the timestamp
flag was set when tracing, the trace
messages from the different logs will be merged according to the
timestamps in each message.
The second argument to ttb:format/2
is a list of
options. The out
option specifies the destination where the
formatted text shall be written. Default destination is
standard_io
, but a filename can also be given. The
handler
option specifies the format handler to use. If this
option is not given, the handler
option given when starting
the tracer is used. If the handler
option was not given
when starting the tracer either, a default handler is used, which
prints each trace message as a line of text.
A format handler is a fun taking four arguments. This fun will be called for each trace message in the binary log(s). A simple example which only prints each trace message could be like this:
fun(Fd, Trace, _TraceInfo, State) -> io:format(Fd, "Trace: ~p~n", [Trace]), State end.
Fd
is the file descriptor for the destination file, or
the atom standard_io
. _TraceInfo
contains information
from the trace information file (see Trace Information and the .ti
File). State
is a state variable for the format
handler fun. The initial value of the State
variable is
given with the handler option, e.g.
ttb:format("tiger@durin-ttb", [{handler, {{Mod,Fun}, initial_state}}]) ^^^^^^^^^^^^^
Another format handler could be used to calculate time spent by the garbage collector:
fun(_Fd,{trace_ts,P,gc_start,_Info,StartTs},_TraceInfo,State) -> [{P,StartTs}|State]; (Fd,{trace_ts,P,gc_end,_Info,EndTs},_TraceInfo,State) -> {value,{P,StartTs}} = lists:keysearch(P,1,State), Time = diff(StartTs,EndTs), io:format("GC in process ~w: ~w milliseconds~n", [P,Time]), State -- [{P,StartTs}] end
A more refined version of this format handler is the function
handle_gc/4
in the module multitrace.erl
which can
be found in the src
directory of the Observer application.
By giving the format handler et
, you can have the trace
log presented graphically with et_viewer
in the Event
Tracer application (see Presenting
trace logs with Event Tracer).
Wrap logs can be formatted one by one or all in one go. To format one of the wrap logs in a set, give the exact name of the file. To format the whole set of wrap logs, give the name with '*' instead of the wrap count. An example:
Start tracing:
(tiger@durin)1> ttb:tracer(node(),[{file,{wrap,"trace"}}]). {ok,[tiger@durin]} (tiger@durin)2> ttb:p(...) ...
This will give a set of binary logs, like:
tiger@durin-trace.0.wrp tiger@durin-trace.1.wrp tiger@durin-trace.2.wrp ...
Format the whole set of logs:
1> ttb:format("tiger@durin-trace.*.wrp"). .... ok 2>
Format only the first log:
1> ttb:format("tiger@durin-trace.0.wrp"). .... ok 2>
To merge all wrap logs from two nodes:
1> ttb:format(["tiger@durin-trace.*.wrp","lion@durin-trace.*.wrp"]). .... ok 2>
For detailed information about the Event Tracer, please turn
to the User's Guide and Reference Manuals for the et
application.
By giving the format handler et
, you can have the
trace log presented graphically with et_viewer
in the
Event Tracer application. ttb
provides a few different
filters which can be selected from the Filter menu in the
et_viewer
window. The filters are names according to the
type of actors they present (i.e. what each vertical line in the
sequence diagram represent). Interaction between actors is shown
as red arrows between two vertical lines, and activities within
an actor are shown as blue text to the right of the actors line.
The processes
filter is the only filter which will
show all trace messages from a trace log. Each vertical line in
the sequence diagram represents a process. Erlang messages,
spawn and link/unlink are typical interactions between
processes. Function calls, scheduling and garbage collection are
typical activities within a process. processes
is the
default filter.
The rest of the filters will only show function calls and
function returns. All other trace message are discarded. To get
the most out of these filters, et_viewer
needs to known
the caller of each function and the time of return. This can be
obtained by using both the call
and return_to
flags when tracing. Note that the return_to
flag only
works with local call trace, i.e. when trace patterns are set
with ttb:tpl
.
The same result can be obtaind by using the call
flag
only and setting a match specification like this on local or
global function calls:
1> dbg:fun2ms(fun(_) -> return_trace(),message(caller()) end). [{'_',[],[{return_trace},{message,{caller}}]}]
This should however be done with care, since the
{return_trace}
function in the match specification will
destroy tail recursiveness.
The modules
filter shows each module as a vertical
line in the sequence diagram. External function calls/returns
are shown as interactions between modules and internal function
calls/returns are shown as activities within a module.
The functions
filter shows each function as a vertical
line in the sequence diagram. A function calling itself is shown
as an activity within a function, and all other function calls
are shown as interactions between functions.
The mods_and_procs
and funcs_and_procs
filters
are equivalent to the modules
and functions
filters respectively, except that each module or function can
have several vertical lines, one for each process it resides on.
As an example this module is used, and the function
bar:f1()
is called from another module foo
.
-module(bar). -export([f1/0,f3/0]). f1() -> f2(), ok. f2() -> spawn(?MODULE,f3,[]). f3() -> ok.
The call
and return_to
flags are used, and
trace pattern is set on local calls in module bar
.
ttb:format("tiger@durin-ttb", [{handler, et}])
gives the
following result:
If the option fetch
is given to the ttb:stop/1
function, trace logs and trace information files are fetched
from all nodes after tracing is stopped. The logs are stored in a
new directory named ttb_upload-Timestamp
under the working
directory of the trace control node.
If the option format
is given to ttb:stop/1
, the
trace logs are automatically formatted after tracing is
stopped. Note that format
also implies fetch
,
i.e. the trace logs will be collected from all nodes as for the
fetch
option before they are formatted. All logs in the
upload directory are merged during formatting.
For the tracing functionality, dbg
could be used instead
of the ttb
for setting trace flags on processes and trace
patterns for call trace, i.e. the functions p
, tp
,
tpl
, ctp
, ctpl
and ctpg
. The only
thing added by ttb
for these functions is that all calls
are stored in the history buffer and can be recalled and stored in
a configuration file. This makes it easy to setup the same trace
environment e.g. if you want to compare two test runs. It also
reduces the amount of typing when using ttb
from the erlang
shell.
Use list_history/0
to see the content of the history
buffer, and run_history/1
to re-execute one of the entries.
The main purpose of the history buffer is the possibility to create configuration files. Any function stored in the history buffer can be written to a configuration file and used for creating a specific configuration at any time with one single function call.
A configuration file is created or extended with
write_config/2/3
. Configuration files are binary files
and can therefore only be read and written with functions provided
by ttb
.
You can write the complete content of the history buffer to a
config file by calling
ttb:write_config(ConfigFile,all)
. And you can write
selected entries from the history by calling
ttb:write_config(ConfigFile,NumList)
, where
NumList
is a list of integers pointing out the history
entries to write.
User defined entries can also be written to a config file by
calling the function
ttb:write_config(ConfigFile,ConfigList)
where
ConfigList
is a list of {Module,Function,Args}
.
Any existing file ConfigFile
is deleted and a new file
is created when write_config/2
is called. The option
append
can be used if you wish to add something at the end
of an existing config file, e.g.
ttb:write_config(ConfigFile,What,[append])
.
See the content of the history buffer
(tiger@durin)191> ttb:tracer(). {ok,[tiger@durin]} (tiger@durin)192> ttb:p(self(),[garbage_collection,call]). {ok,{[<0.1244.0>],[garbage_collection,call]}} (tiger@durin)193> ttb:tp(ets,new,2,[]). {ok,[{matched,1}]} (tiger@durin)194> ttb:list_history(). [{1,{ttb,tracer,[tiger@durin,[]]}}, {2,{ttb,p,[<0.1244.0>,[garbage_collection,call]]}}, {3,{ttb,tp,[ets,new,2,[]]}}]
Execute an entry from the history buffer:
(tiger@durin)195> ttb:ctp(ets,new,2). {ok,[{matched,1}]} (tiger@durin)196> ttb:list_history(). [{1,{ttb,tracer,[tiger@durin,[]]}}, {2,{ttb,p,[<0.1244.0>,[garbage_collection,call]]}}, {3,{ttb,tp,[ets,new,2,[]]}}, {4,{ttb,ctp,[ets,new,2]}}] (tiger@durin)197> ttb:run_history(3). ttb:tp(ets,new,2,[]) -> {ok,[{matched,1}]}
Write the content of the history buffer to a configuration file:
(tiger@durin)198> ttb:write_config("myconfig",all). ok (tiger@durin)199> ttb:list_config("myconfig"). [{1,{ttb,tracer,[tiger@durin,[]]}}, {2,{ttb,p,[<0.1244.0>,[garbage_collection,call]]}}, {3,{ttb,tp,[ets,new,2,[]]}}, {4,{ttb,ctp,[ets,new,2]}}, {5,{ttb,tp,[ets,new,2,[]]}}]
Extend an existing configuration:
(tiger@durin)200> ttb:write_config("myconfig",[{ttb,tp,[ets,delete,1,[]]}], [append]). ok (tiger@durin)201> ttb:list_config("myconfig"). [{1,{ttb,tracer,[tiger@durin,[]]}}, {2,{ttb,p,[<0.1244.0>,[garbage_collection,call]]}}, {3,{ttb,tp,[ets,new,2,[]]}}, {4,{ttb,ctp,[ets,new,2]}}, {5,{ttb,tp,[ets,new,2,[]]}}, {6,{ttb,tp,[ets,delete,1,[]]}}]
Go back to a previous configuration after stopping Trace Tool Builder:
(tiger@durin)202> ttb:stop(). ok (tiger@durin)203> ttb:run_config("myconfig"). ttb:tracer(tiger@durin,[]) -> {ok,[tiger@durin]} ttb:p(<0.1244.0>,[garbage_collection,call]) -> {ok,{[<0.1244.0>],[garbage_collection,call]}} ttb:tp(ets,new,2,[]) -> {ok,[{matched,1}]} ttb:ctp(ets,new,2) -> {ok,[{matched,1}]} ttb:tp(ets,new,2,[]) -> {ok,[{matched,1}]} ttb:tp(ets,delete,1,[]) -> {ok,[{matched,1}]} ok
Write selected entries from the history buffer to a configuration file:
(tiger@durin)204> ttb:list_history(). [{1,{ttb,tracer,[tiger@durin,[]]}}, {2,{ttb,p,[<0.1244.0>,[garbage_collection,call]]}}, {3,{ttb,tp,[ets,new,2,[]]}}, {4,{ttb,ctp,[ets,new,2]}}, {5,{ttb,tp,[ets,new,2,[]]}}, {6,{ttb,tp,[ets,delete,1,[]]}}] (tiger@durin)205> ttb:write_config("myconfig",[1,2,3,6]). ok (tiger@durin)206> ttb:list_config("myconfig"). [{1,{ttb,tracer,[tiger@durin,[]]}}, {2,{ttb,p,[<0.1244.0>,[garbage_collection,call]]}}, {3,{ttb,tp,[ets,new,2,[]]}}, {4,{ttb,tp,[ets,delete,1,[]]}}] (tiger@durin)207>
To learn what sequential tracing is and how it can be used,
please turn to the reference manual for the
seq_trace
module in the kernel
application.
The support for sequencial tracing provided by the Trace Tool Builder includes
ttb:tracer/0/1/2
Starting sequential tracing requires that a tracer has been
started with the ttb:tracer/0/1/2
function. Sequential
tracing can then either be started via a trigger function with a
match specification created with ttb:seq_trigger_ms/0/1
,
or directly by using the seq_trace
module in the
kernel
application.
In the following example, the function
dbg:get_tracer/0
is used as trigger for sequential
tracing:
(tiger@durin)110> ttb:tracer(). {ok,[tiger@durin]} (tiger@durin)111> ttb:p(self(),call). {ok,{[<0.158.0>],[call]}} (tiger@durin)112> ttb:tp(dbg,get_tracer,0,ttb:seq_trigger_ms(send)). {ok,[{matched,1},{saved,1}]} (tiger@durin)113> dbg:get_tracer(), seq_trace:reset_trace(). true (tiger@durin)114> ttb:stop(). ok (tiger@durin)115> ttb:format("tiger@durin-ttb"). ({<0.158.0>,{shell,evaluator,3},tiger@durin}) call dbg:get_tracer() SeqTrace [0]: ({<0.158.0>,{shell,evaluator,3},tiger@durin}) {<0.237.0>,dbg,tiger@durin} ! {<0.158.0>,{get_tracer,tiger@durin}} [Serial: {0,1}] SeqTrace [0]: ({<0.237.0>,dbg,tiger@durin}) {<0.158.0>,{shell,evaluator,3},tiger@durin} ! {dbg,{ok,#Port<0.222>}} [Serial: {1,2}] ok (tiger@durin)116>
Starting sequential tracing with a trigger is actually more useful if the trigger function is not called directly from the shell, but rather implicitly within a larger system. When calling a function from the shell, it is simpler to start sequential tracing directly, e.g.
(tiger@durin)116> ttb:tracer(). {ok,[tiger@durin]} (tiger@durin)117> seq_trace:set_token(send,true), dbg:get_tracer(), seq_trace:reset_trace(). true (tiger@durin)118> ttb:stop(). ok (tiger@durin)119> ttb:format("tiger@durin-ttb"). SeqTrace [0]: ({<0.158.0>,{shell,evaluator,3},tiger@durin}) {<0.246.0>,dbg,tiger@durin} ! {<0.158.0>,{get_tracer,tiger@durin}} [Serial: {0,1}] SeqTrace [0]: ({<0.246.0>,dbg,tiger@durin}) {<0.158.0>,{shell,evaluator,3},tiger@durin} ! {dbg,{ok,#Port<0.229>}} [Serial: {1,2}] ok (tiger@durin)120>
In both examples above, the seq_trace:reset_trace/0
resets the trace token immediately after the traced function in
order to avoid lots of trace messages due to the printouts in
the erlang shell.
All functions in the seq_trace
module, except
set_system_tracer/1
, can be used after the trace port has
been started with ttb:tracer/0/1/2
.
The module multitrace.erl
which can be found in the
src
directory of the Observer application implements a
small tool with three possible trace settings. The trace messages
are written to binary files which can be formatted with the
function multitrace:format/1/2
.
multitrace:debug(What)
multitrace:handle_debug/4
which prints each call and
return. What
must be an item or a list of items to trace,
given on the format {Module,Function,Arity}
,
{Module,Function}
or just Module
.
multitrace:gc(Procs)
multitrace:handle_gc/4
which
prints start and stop and the time spent for each GC.
multitrace:schedule(Procs)
multitrace:handle_schedule/4
which
prints each in and out scheduling with process, timestamp and
current function. It also prints the total time each traced
process was scheduled in.