<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html xmlns:fn="http://www.w3.org/2005/02/xpath-functions">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
<link rel="stylesheet" href="../../../../doc/otp_doc.css" type="text/css">
<title>Erlang -- Trace Tool Builder</title>
</head>
<body bgcolor="white" text="#000000" link="#0000ff" vlink="#ff00ff" alink="#ff0000"><div id="container">
<script id="js" type="text/javascript" language="JavaScript" src="../../../../doc/js/flipmenu/flipmenu.js"></script><script id="js2" type="text/javascript" src="../../../../doc/js/erlresolvelinks.js"></script><script language="JavaScript" type="text/javascript">
<!--
function getWinHeight() {
var myHeight = 0;
if( typeof( window.innerHeight ) == 'number' ) {
//Non-IE
myHeight = window.innerHeight;
} else if( document.documentElement && ( document.documentElement.clientWidth ||
document.documentElement.clientHeight ) ) {
//IE 6+ in 'standards compliant mode'
myHeight = document.documentElement.clientHeight;
} else if( document.body && ( document.body.clientWidth || document.body.clientHeight ) ) {
//IE 4 compatible
myHeight = document.body.clientHeight;
}
return myHeight;
}
function setscrollpos() {
var objf=document.getElementById('loadscrollpos');
document.getElementById("leftnav").scrollTop = objf.offsetTop - getWinHeight()/2;
}
function addEvent(obj, evType, fn){
if (obj.addEventListener){
obj.addEventListener(evType, fn, true);
return true;
} else if (obj.attachEvent){
var r = obj.attachEvent("on"+evType, fn);
return r;
} else {
return false;
}
}
addEvent(window, 'load', setscrollpos);
//--></script><div id="leftnav"><div class="innertube">
<img alt="Erlang logo" src="../../../../doc/erlang-logo.png"><br><small><a href="users_guide.html">User's Guide</a><br><a href="index.html">Reference Manual</a><br><a href="release_notes.html">Release Notes</a><br><a href="../pdf/observer-1.2.pdf">PDF</a><br><a href="../../../../doc/index.html">Top</a></small><p><strong>Observer</strong><br><strong>User's Guide</strong><br><small>Version 1.2</small></p>
<br><a href="javascript:openAllFlips()">Expand All</a><br><a href="javascript:closeAllFlips()">Contract All</a><p><small><strong>Chapters</strong></small></p>
<ul class="flipMenu" imagepath="../../../../doc/js/flipmenu">
<li id="no" title="Observer" expanded="false">Observer<ul>
<li><a href="observer_ug.html">
Top of chapter
</a></li>
<li title="Introduction"><a href="observer_ug.html#id61965">Introduction</a></li>
<li title="General"><a href="observer_ug.html#id63021">General</a></li>
<li title="Applications"><a href="observer_ug.html#id61978">Applications</a></li>
<li title="Processes"><a href="observer_ug.html#id58232">Processes</a></li>
<li title="Table Viewer"><a href="observer_ug.html#id61813">Table Viewer</a></li>
<li title="Trace Overview"><a href="observer_ug.html#id58317">Trace Overview</a></li>
</ul>
</li>
<li id="loadscrollpos" title="Trace Tool Builder" expanded="true">Trace Tool Builder<ul>
<li><a href="ttb_ug.html">
Top of chapter
</a></li>
<li title="Introduction"><a href="ttb_ug.html#id62654">Introduction</a></li>
<li title="Getting Started"><a href="ttb_ug.html#id62682">Getting Started</a></li>
<li title="Running the Trace Tool Builder against a remote node"><a href="ttb_ug.html#id62166">Running the Trace Tool Builder against a remote node</a></li>
<li title="Additional tracing options"><a href="ttb_ug.html#id59987">Additional tracing options</a></li>
<li title="Trace Information and the .ti File"><a href="ttb_ug.html#id62926">Trace Information and the .ti File</a></li>
<li title="Wrap Logs"><a href="ttb_ug.html#id61480">Wrap Logs</a></li>
<li title="Formatting"><a href="ttb_ug.html#id61519">Formatting</a></li>
<li title="Automatically collect and format logs from all nodes"><a href="ttb_ug.html#id62581">Automatically collect and format logs from all nodes</a></li>
<li title="History and Configuration Files"><a href="ttb_ug.html#id63031">History and Configuration Files</a></li>
<li title="Sequential Tracing"><a href="ttb_ug.html#id63279">Sequential Tracing</a></li>
<li title="Example: Multipurpose trace tool"><a href="ttb_ug.html#id63411">Example: Multipurpose trace tool</a></li>
</ul>
</li>
<li id="no" title="Erlang Top" expanded="false">Erlang Top<ul>
<li><a href="etop_ug.html">
Top of chapter
</a></li>
<li title="Introduction"><a href="etop_ug.html#id64602">Introduction</a></li>
<li title="Output"><a href="etop_ug.html#id64621">Output</a></li>
<li title="Start"><a href="etop_ug.html#id64768">Start</a></li>
<li title="Configuration"><a href="etop_ug.html#id64805">Configuration</a></li>
<li title="Print to file"><a href="etop_ug.html#id64958">Print to file</a></li>
<li title="Stop"><a href="etop_ug.html#id64985">Stop</a></li>
</ul>
</li>
<li id="no" title="Crashdump Viewer" expanded="false">Crashdump Viewer<ul>
<li><a href="crashdump_ug.html">
Top of chapter
</a></li>
<li title="Introduction"><a href="crashdump_ug.html#id65063">Introduction</a></li>
<li title="Getting Started"><a href="crashdump_ug.html#id65075">Getting Started</a></li>
<li title="Navigating"><a href="crashdump_ug.html#id65156">Navigating</a></li>
<li title="Help"><a href="crashdump_ug.html#id65186">Help</a></li>
</ul>
</li>
</ul>
</div></div>
<div id="content">
<div class="innertube">
<h1>2 Trace Tool Builder</h1>
<h3><a name="id62654">2.1
Introduction</a></h3>
<p>The Trace Tool Builder is a base for building trace tools for
single node or distributed erlang systems. It requires the
<span class="code">runtime_tools</span> application to be available on the traced
node.
</p>
<p>The main features of the Trace Tool Builder are:</p>
<ul>
<li>Start tracing to file ports on several nodes with one
function call.</li>
<li>Write additional information to a trace information file,
which is read during formatting.</li>
<li>Restoring of previous configuration by maintaining a
history buffer and handling configuration files.</li>
<li>Some simple support for sequential tracing.</li>
<li>Formatting of binary trace logs and merging of logs from
multiple nodes.</li>
</ul>
<p>The intention of the Trace Tool Builder is to serve
as a base for tailor made trace tools, but you may use it directly
from the erlang shell (it may mimic <span class="code">dbg</span> behaviour while
still providing useful additions like match specification shortcuts).
The application only
allows the use of file port tracer, so if you would like
to use other types of trace clients you will be better off
using <span class="code">dbg</span> directly instead.</p>
<h3><a name="id62682">2.2
Getting Started</a></h3>
<p>The <span class="code">ttb</span> 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 <span class="code">ttb:tracer/0/1/2</span>, and set the required
trace flags on the processes you want to trace with
<span class="code">ttb:p/2</span>. Then, when the tracing is completed, you must stop
the tracer with <span class="code">ttb:stop/0/1</span> and format the trace log with
<span class="code">ttb:format/1/2</span> (as long as there is anything to format, of
course).
</p>
<p><span class="code">ttb:tracer/0/1/2</span> opens a trace port on each node
that shall be traced. By default, trace messages are written
to binary files on remote nodes(the binary trace log).
</p>
<p><span class="code">ttb:p/2</span> specifies which processes shall be
traced. Trace flags given in this call specify 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.
</p>
<p>If you want to trace function calls (i.e. if you have the
<span class="code">call</span> trace flag set on any of your processes), you must
also set trace patterns on the required function(s) with
<span class="code">ttb:tp</span> or <span class="code">ttb:tpl</span>. 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
<span class="code">erts</span>.
</p>
<p><span class="code">ttb:stop/0/1</span> stops tracing on all nodes, deletes all
trace patterns and flushes the trace port buffer.
</p>
<p><span class="code">ttb:format/1/2</span> translates the binary trace logs into
something readable. By default <span class="code">ttb</span> 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 <span class="code">format</span> option to
<span class="code">ttb:stop/1</span> the formatting is automatically done when
stopping <span class="code">ttb</span>.
</p>
<h4>Example: Tracing the local node from the erlang shell</h4>
<p>This small module is used in the example:</p>
<div class="example"><pre>
-module(m).
-export([f/0]).
f() ->
receive
From when is_pid(From) ->
Now = erlang:now(),
From ! {self(),Now}
end. </pre></div>
<p>The following example shows the basic use of <span class="code">ttb</span> from
the erlang shell. Default options are used both for starting the
tracer and for formatting (the custom fetch dir is however provided).
This gives a trace log named <span class="code">Node-ttb</span> in the newly-created
directory, where <span class="code">Node</span> is the name of the node. The
default handler prints the formatted trace messages in the
shell.</p>
<div class="example"><pre>
(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> %% indicating that the return value should be
(tiger@durin)50> %% traced. Refer to the reference_manual for
(tiger@durin)50> %% the full list of match spec shortcuts
(tiger@durin)50> %% available.
(tiger@durin)51> ttb:tp(erlang,now,return).
{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([return, {fetch_dir, "fetch"}]).
{stopped, "fetch"}
(tiger@durin)54>
(tiger@durin)54> %% Finally I format my trace log
(tiger@durin)54> ttb:format("fetch").
({<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 </pre></div>
<h4>Example: Build your own tool</h4>
<p>This small example shows a simple tool for "debug tracing",
i.e. tracing of function calls with return values.</p>
<div class="example"><pre>
-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
%% We want trace messages to be sorted upon format, which requires
%% timestamp flag. The flag is however enabled by default in ttb.
ttb:p(all,call).
%%% Set trace pattern on function(s)
trc(M) when is_atom(M) ->
trc({M,'_','_'});
trc({M,F}) when is_atom(M), is_atom(F) ->
trc({M,F,'_'});
trc({M,F,_A}=MFA) when is_atom(M), is_atom(F) ->
%% This match spec shortcut specifies that return values shall
%% be traced.
MatchSpec = dbg:fun2ms(fun(_) -> return_trace() end),
ttb:tpl(MFA,MatchSpec).
%%% Format a binary trace log
format(Dir) ->
ttb:format(Dir).
%%% Stop the "mydebug" tool
stop() ->
ttb:stop(return).
%%% --------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]). </pre></div>
<p>To distinguish trace logs produced with this tool from other
logs, the <span class="code">file</span> option is used in <span class="code">tracer/2</span>. The
logs will therefore be fetched to a directory named
<span class="code">ttb_upload_debug_log-YYYYMMDD-HHMMSS</span>
</p>
<p>By using the <span class="code">handler</span> option when starting the tracer,
the information about how to format the file is stored in the
trace information file (<span class="code">.ti</span>). 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 <span class="code">format</span> option in
<span class="code">ttb:stop/1</span>. 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 <span class="code">handler</span> option is given
both when starting the tracer and when formatting, the one given
when formatting is used.
</p>
<p>The <span class="code">call</span> trace flag is set on all processes. This
means that any function activated with the <span class="code">trc/1</span> command
will be traced on all existing and new processes.
</p>
<h3><a name="id62166">2.3
Running the Trace Tool Builder against a remote node</a></h3>
<p>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
</p>
<ul>
<li>The Observer application is available on the trace control node.</li>
<li>The Runtime Tools application is available on both the
trace control node and the traced node.</li>
</ul>
<p>If the Trace Tool Builder shall be used against a remote node,
it is highly recommended to start the trace control node as
<strong>hidden</strong>. This way it can connect to the traced node
without the traced node "seeing" it, i.e. if the <span class="code">nodes()</span>
BIF is called on the traced node, the trace control node will not
show. To start a hidden node, add the <span class="code">-hidden</span> option to the
<span class="code">erl</span> command, e.g.</p>
<div class="example"><pre>
% erl -sname trace_control -hidden </pre></div>
<h4>Diskless node</h4>
<p>If the traced node is diskless, <span class="code">ttb</span> must be started from
a trace control node with disk access, and the <span class="code">file</span> option
must be given to the <span class="code">tracer/2</span> function with the value
<span class="code">{local, File}</span>, e.g.</p>
<div class="example"><pre>
(trace_control@durin)1> ttb:tracer(mynode@diskless,{file,{local,
{wrap,"mytrace"}}}).
{ok,[mynode@diskless]} </pre></div>
<h3><a name="id59987">2.4
Additional tracing options</a></h3>
<p>When setting up a trace, several features may be turned on:</p>
<ul>
<li>time-constrained tracing,</li>
<li>overload protection,</li>
<li>autoresuming.</li>
</ul>
<h4>Time-constrained tracing</h4>
<p>Sometimes, it may be helpful to enable trace for a
given period of time (i.e. to monitor a system for 24 hours
or half of a second). This may be done by issuing additional
<span class="code">{timer, TimerSpec}</span> option. If <span class="code">TimerSpec</span> has the
form of <span class="code">MSec</span>, the trace is stopped after <span class="code">MSec</span>
milliseconds using <span class="code">ttb:stop/0</span>. If any additional options
are provided (<span class="code">TimerSpec = {MSec, Opts}</span>), <span class="code">ttb:stop/1</span>
is called instead with <span class="code">Opts</span> as the arguments. The timer
is started with <span class="code">ttb:p/2</span>, so any trace patterns should
be set up before. <span class="code">ttb:start_trace/4</span>
always sets up all pattern before invoking <span class="code">ttb:p/2</span>.
Note that due to network and processing delays the the period
of tracing is approximate.
The example below shows how to set up a trace which will be
automatically stopped and formatted after 5 seconds
</p>
<div class="example"><pre>
(tiger@durin)1>ttb:start_trace([node()],
[{erlang, now,[]}],
{all, call},
[{timer, {5000, format}}]).
</pre></div>
<h4></h4>
Overload protection
<p>When tracing live systems, special care needs to be always taken
not to overload a node with too heavy tracing. <span class="code">ttb</span> provides
the <span class="code">overload</span> option to help to address the problem.</p>
<p><span class="code">{overload, MSec, Module, Function}</span> instructs the ttb backend
(called <span class="code">observer_backend</span>, part of the <span class="code">runtime_tools</span>
application) to perform overload check every <span class="code">MSec</span> milliseconds.
If the check (namely <span class="code">Module:Function(check)</span>) returns
<span class="code">true</span>, tracing is disabled on the selected node.</p>
<p>Overload protection activated on one node does not
affect other nodes, where the tracing continues as normal.
<span class="code">ttb:stop/0/1</span> fetches data from all clients, including everything
that has been collected before overload protection was activated.
Note that
changing trace details (with <span class="code">ttb:p</span> and <span class="code">ttb:tp/tpl...</span>)
once overload protection gets activated in one of the traced
nodes is not permitted in order not to allow trace setup
to be inconsistent between nodes.
</p>
<p><span class="code">Module:Function</span> provided with the <span class="code">overload</span> option must
handle three calls: <span class="code">init</span>, <span class="code">check</span> and <span class="code">stop</span>. <span class="code">init</span>
and <span class="code">stop</span> allows to perform some setup and teardown required by
the check. An overload check module could look like this (note that
<span class="code">check</span> is always called by the same process, so <span class="code">put</span> and
<span class="code">get</span> are possible).
</p>
<div class="example"><pre>
-module(overload).
-export([check/1]).
check(init) ->
Pid = sophisticated_module:start(),
put(pid, Pid);
check(check) ->
get(pid) ! is_overloaded,
receive
Reply ->
Reply
after 5000 ->
true
end;
check(stop) ->
get(pid) ! stop.</pre></div>
<h4>Autoresume</h4>
<p>It is possible that a node (probably a buggy one, hence traced)
crashes. In order to automatically resume tracing on the node
as soon as it gets back, <span class="code">resume</span> has to be used. When
it is, the failing node tries to reconnect
to trace control node as soon as <span class="code">runtime tools</span> is started.
This implies that <span class="code">runtime_tools</span> must be included in
other node's startup chain (if it is not, one could still
resume tracing by starting <span class="code">runtime_tools</span> manually,
i.e. by an RPC call).</p>
<p>In order not to loose the data that the failing node stored
up to the point of crash, the control node will try to fetch
it before restarting trace. This must happen within the allowed
time frame or is aborted (default is 10 seconds, can be customized with
<span class="code">{resume, MSec}</span>). The data fetched this way is then
merged with all other traces.</p>
<p>Autostart feature requires additional data to be stored on
traced nodes. By default, the data is stored automatically
to the file called "ttb_autostart.bin" in the traced node's cwd.
Users may decide to change this behaviour (i.e. on diskless
nodes) by specifying their own module to handle autostart data
storage and retrieval (<span class="code">ttb_autostart_module</span>
environment variable of <span class="code">runtime_tools</span>). Please see the
ttb's reference manual to see the module's API. This example
shows the default handler</p>
<div class="example"><pre>
-module(ttb_autostart).
-export([read_config/0,
write_config/1,
delete_config/0]).
-define(AUTOSTART_FILENAME, "ttb_autostart.bin").
delete_config() ->
file:delete(?AUTOSTART_FILENAME).
read_config() ->
case file:read_file(?AUTOSTART_FILENAME) of
{ok, Data} -> {ok, binary_to_term(Data)};
Error -> Error
end.
write_config(Data) ->
file:write_file(?AUTOSTART_FILENAME, term_to_binary(Data)).
</pre></div>
<p>Remember that file trace ports buffer the data
by default. If the node crashes, trace messages are not
flushed to the binary log. If the chance of failure is
high, it might be a good idea to automatically flush
the buffers every now and then. Passing <span class="code">{flush, MSec}</span>
as one of <span class="code">ttb:tracer/2</span> option flushes all buffers
every <span class="code">MSec</span> milliseconds.</p>
<h4>dbg mode</h4>
<p>The <span class="code">{shell, ShellType}</span> option allows to make <span class="code">ttb</span>
operation similar to <span class="code">dbg</span>. Using <span class="code">{shell, true}</span>
displays all trace messages in the shell before storing them.
<span class="code">{shell, only}</span> additionally disables message storage
(so that the tool behaves exactly like dbg). This is allowed
only with ip trace ports (<span class="code">{trace, {local, File}}</span>).
</p>
<p>The command <span class="code">ttb:tracer(dbg)</span> is a shortcut for the pure-dbg
mode (<span class="code">{shell, only}</span>).</p>
<h3><a name="id62926">2.5
Trace Information and the .ti File</a></h3>
<a name="trace_info"></a>
<p>In addition to the trace log file(s), a file with the extension
<span class="code">.ti</span> 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
<span class="code">write_trace_info/2</span> function. .ti files are always fetched
with other logs when the trace is stopped.
</p>
<p>Except for the process information, everything in the trace
information file is passed on to the handler function when
formatting. The <span class="code">TI</span> parameter is a list of
<span class="code">{Key,ValueList}</span> tuples. The keys <span class="code">flags</span>,
<span class="code">handler</span>, <span class="code">file</span> and <span class="code">node</span> are used for
information written directly by <span class="code">ttb</span>.
</p>
<p>You can add information to the trace information file by
calling <span class="code">write_trace_info/2</span>. Note that <span class="code">ValueList</span>
always will be a list, and if you call <span class="code">write_trace_info/2</span>
several times with the same <span class="code">Key</span>, the <span class="code">ValueList</span> will
be extended with a new value each time. Example:
</p>
<p><span class="code">ttb:write_trace_info(mykey,1)</span> gives the entry
<span class="code">{mykey,[1]}</span> in <span class="code">TI</span>. Another call,
<span class="code">ttb:write_trace_info(mykey,2)</span>, changes this entry to
<span class="code">{mykey,[1,2]}</span>.
</p>
<h3><a name="id61480">2.6
Wrap Logs</a></h3>
<p>If you want to limit the size of the trace logs, you can use
wrap logs. This works almost like a circular buffer. You can
specify the maximum number of binary logs and the maximum size of
each log. <span class="code">ttb</span> 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.
</p>
<p>Note that the overall size of data generated by ttb may be greater
than the wrap specification would suggest - if a traced node restarts
and autoresume is enabled, old wrap log is always stored and
a new one is created.
</p>
<p>Wrap logs can be formatted one by one or all at once. See
<span class="bold_code"><a href="#format">Formatting</a></span>.
</p>
<h3><a name="id61519">2.7
Formatting</a></h3>
<a name="format"></a>
<p>Formatting can be done automatically when stopping <span class="code">ttb</span>
(see <span class="bold_code"><a href="#fetch_format">Automatically collect and format logs from all nodes</a></span>), or explicitly by calling
the <span class="code">ttb:format/1/2</span> function.
</p>
<p>Formatting means to read a binary log and present it in a
readable format. You can use the default format handler in
<span class="code">ttb</span> 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 <span class="code">et</span> to
present the trace log graphically (see <span class="bold_code"><a href="#et_viewer">Presenting trace logs with Event Tracer</a></span>).
</p>
<p>The first argument to <span class="code">ttb:format/1/2</span> specifies which
binary log(s) to format. This is usually the name of a directory
that ttb created during log fetch. Unless there is the <span class="code">disable_sort</span>
option provided, the logs from different files are always sorted
according to timestamp in traces.
</p>
<p>The second argument to <span class="code">ttb:format/2</span> is a list of
options. The <span class="code">out</span> option specifies the destination where the
formatted text shall be written. Default destination is
<span class="code">standard_io</span>, but a filename can also be given. The
<span class="code">handler</span> option specifies the format handler to use. If this
option is not given, the <span class="code">handler</span> option given when starting
the tracer is used. If the <span class="code">handler</span> option was not given
when starting the tracer either, a default handler is used, which
prints each trace message as a line of text. The <span class="code">disable_sort</span>
option indicates that there logs should not be merged according to
timestamp, but processed one file after another (this might be
a bit faster).
</p>
<p>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:</p>
<div class="example"><pre>
fun(Fd, Trace, _TraceInfo, State) ->
io:format(Fd, "Trace: ~p~n", [Trace]),
State
end. </pre></div>
<p><span class="code">Fd</span> is the file descriptor for the destination file, or
the atom <span class="code">standard_io</span>. <span class="code">_TraceInfo</span> contains information
from the trace information file (see <span class="bold_code"><a href="#trace_info">Trace Information and the .ti File</a></span>). <span class="code">State</span> is a state variable for the format
handler fun. The initial value of the <span class="code">State</span> variable is
given with the handler option, e.g.</p>
<div class="example"><pre>
ttb:format("tiger@durin-ttb", [{handler, {{Mod,Fun}, initial_state}}])
^^^^^^^^^^^^^ </pre></div>
<p>Another format handler could be used to calculate time spent by
the garbage collector:</p>
<div class="example"><pre>
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 </pre></div>
<p>A more refined version of this format handler is the function
<span class="code">handle_gc/4</span> in the module <span class="code">multitrace.erl</span> which can
be found in the <span class="code">src</span> directory of the Observer application.
</p>
<p>The actual trace message is passed as the second argument (<span class="code">Trace</span>).
The possible values of <span class="code">Trace</span> are:</p>
<ul>
<li>all trace messages described in <span class="code">erlang:trace/3</span> documentation,
</li>
<li>
<span class="code">{drop, N}</span> if ip tracer is used (see <span class="code">dbg:trace_port/2</span>),
</li>
<li>
<span class="code">end_of_trace</span> received once when all trace messages have
been processed.</li>
</ul>
<p>By giving the format handler <span class="code">ttb:get_et_handler()</span>, you can have the trace
log presented graphically with <span class="code">et_viewer</span> in the Event
Tracer application (see <span class="bold_code"><a href="#et_viewer">Presenting trace logs with Event Tracer</a></span>).
</p>
<p>You may always decide not to format the whole trace data contained
in the fetch directory, but analyze single files instead. In order
to do so, a single file (or list of files) have to be passed as
the first argument to <span class="code">format/1/2</span>.</p>
<p>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:
</p>
<p>Start tracing:</p>
<div class="example"><pre>
(tiger@durin)1> ttb:tracer(node(),{file,{wrap,"trace"}}).
{ok,[tiger@durin]}
(tiger@durin)2> ttb:p(...)
... </pre></div>
<p>This will give a set of binary logs, like:</p>
<div class="example"><pre>
tiger@durin-trace.0.wrp
tiger@durin-trace.1.wrp
tiger@durin-trace.2.wrp
... </pre></div>
<p>Format the whole set of logs:</p>
<div class="example"><pre>
1> ttb:format("tiger@durin-trace.*.wrp").
....
ok
2> </pre></div>
<p>Format only the first log:</p>
<div class="example"><pre>
1> ttb:format("tiger@durin-trace.0.wrp").
....
ok
2> </pre></div>
<p>To merge all wrap logs from two nodes:</p>
<div class="example"><pre>
1> ttb:format(["tiger@durin-trace.*.wrp","lion@durin-trace.*.wrp"]).
....
ok
2> </pre></div>
<h4>Presenting trace logs with Event Tracer</h4>
<a name="et_viewer"></a>
<p>For detailed information about the Event Tracer, please turn
to the User's Guide and Reference Manuals for the <span class="code">et</span>
application.
</p>
<p>By giving the format handler <span class="code">ttb:get_et_handler()</span>, you can have the
trace log presented graphically with <span class="code">et_viewer</span> in the
Event Tracer application. <span class="code">ttb</span> provides a few different
filters which can be selected from the Filter menu in the
<span class="code">et_viewer</span> 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.
</p>
<p>The <span class="code">processes</span> 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. <span class="code">processes</span> is the
default filter.
</p>
<p>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, <span class="code">et_viewer</span> needs to known
the caller of each function and the time of return. This can be
obtained by using both the <span class="code">call</span> and <span class="code">return_to</span>
flags when tracing. Note that the <span class="code">return_to</span> flag only
works with local call trace, i.e. when trace patterns are set
with <span class="code">ttb:tpl</span>.
</p>
<p>The same result can be obtained by using the <span class="code">call</span> flag
only and setting a match specification like this on local or
global function calls:</p>
<div class="example"><pre>
1> dbg:fun2ms(fun(_) -> return_trace(),message(caller()) end).
[{'_',[],[{return_trace},{message,{caller}}]}] </pre></div>
<p>This should however be done with care, since the
<span class="code">{return_trace}</span> function in the match specification will
destroy tail recursiveness.
</p>
<p>The <span class="code">modules</span> 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.
</p>
<p>The <span class="code">functions</span> 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.
</p>
<p>The <span class="code">mods_and_procs</span> and <span class="code">funcs_and_procs</span> filters
are equivalent to the <span class="code">modules</span> and <span class="code">functions</span>
filters respectively, except that each module or function can
have several vertical lines, one for each process it resides on.
</p>
<p>In the next example, modules <span class="code">foo</span> and <span class="code">bar</span> are used:</p>
<div class="example"><pre>
-module(foo).
-export([start/0,go/0]).
start() ->
spawn(?MODULE, go, []).
go() ->
receive
stop ->
ok;
go ->
bar:f1(),
go()
end.
</pre></div>
<div class="example"><pre>
-module(bar).
-export([f1/0,f3/0]).
f1() ->
f2(),
ok.
f2() ->
spawn(?MODULE,f3,[]).
f3() ->
ok.</pre></div>
<p>Now let's set up the trace.</p>
<div class="example"><pre>
(tiger@durin)1>%%First we retrieve the Pid to limit traced processes set
(tiger@durin)1>Pid = foo:start().
(tiger@durin)2>%%Now we set up tracing
(tiger@durin)2>ttb:tracer().
(tiger@durin)3>ttb:p(Pid, [call, return_to, procs, set_on_spawn]).
(tiger@durin)4>ttb:tpl(bar, []).
(tiger@durin)5>%%Invoke our test function and see output with et viewer
(tiger@durin)5>Pid ! go.
(tiger@durin)6>ttb:stop({format, {handler, ttb:get_et_handler()}}).
</pre></div>
<p>This shoud render a result similar to the
following:
</p>
<p></p>
<img alt="IMAGE MISSING" src="et_processes.gif"><br>
<em>Figure
2.1:
Filter: "processes"</em>
<img alt="IMAGE MISSING" src="et_modsprocs.gif"><br>
<em>Figure
2.2:
Filter: "mods_and_procs"</em>
<p>Note, that we can use <span class="code">ttb:start_trace/4</span> function to help
us here:</p>
<div class="example"><pre>
(tiger@durin)1>Pid = foo:start().
(tiger@durin)2>ttb:start_trace([node()],
[{bar,[]}],
{Pid, [call, return_to, procs, set_on_spawn]}
{handler, ttb:get_et_handler()}).
(tiger@durin)3>Pid ! go.
(tiger@durin)4>ttb:stop(format).
</pre></div>
<h3><a name="id62581">2.8
Automatically collect and format logs from all nodes</a></h3>
<a name="fetch_format"></a>
<p>By default <span class="code">ttb:stop/1</span> fetches trace logs and
trace information files from all nodes. The logs are stored in a
new directory named <span class="code">ttb_upload-Filename-Timestamp</span> under the working
directory of the trace control node. Fetching may be disabled by
providing the <span class="code">nofetch</span> option to <span class="code">ttb:stop/1</span>. User can
specify a fetch directory of his choice passing the
<span class="code">{fetch_dir, Dir}</span> option.
</p>
<p>If the option <span class="code">format</span> is given to <span class="code">ttb:stop/1</span>, the
trace logs are automatically formatted after tracing is
stopped.
</p>
<h3><a name="id63031">2.9
History and Configuration Files</a></h3>
<p>For the tracing functionality, <span class="code">dbg</span> could be used instead
of the <span class="code">ttb</span> for setting trace flags on processes and trace
patterns for call trace, i.e. the functions <span class="code">p</span>, <span class="code">tp</span>,
<span class="code">tpl</span>, <span class="code">ctp</span>, <span class="code">ctpl</span> and <span class="code">ctpg</span>. There are only
two things added by <span class="code">ttb</span> for these functions:
<ul>
<li>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 <span class="code">ttb</span> from the erlang shell;</li>
<li>shortcuts are provided for the most common match
specifications (in order not to force the user to use
<span class="code">dbg:fun2ms</span> continually</li>).
</ul>
</p>
<p>Use <span class="code">list_history/0</span> to see the content of the history
buffer, and <span class="code">run_history/1</span> to re-execute one of the entries.
</p>
<p>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.
</p>
<p>A configuration file is created or extended with
<span class="code">write_config/2/3</span>. Configuration files are binary files
and can therefore only be read and written with functions provided
by <span class="code">ttb</span>.
</p>
<p>You can write the complete content of the history buffer to a
config file by calling
<span class="code">ttb:write_config(ConfigFile,all)</span>. And you can write
selected entries from the history by calling
<span class="code">ttb:write_config(ConfigFile,NumList)</span>, where
<span class="code">NumList</span> is a list of integers pointing out the history
entries to write. Moreover, the history buffer is always dumped
to <span class="code">ttb_last_config</span> when <span class="code">ttb:stop/0/1</span> is called.
</p>
<p>User defined entries can also be written to a config file by
calling the function
<span class="code">ttb:write_config(ConfigFile,ConfigList)</span> where
<span class="code">ConfigList</span> is a list of <span class="code">{Module,Function,Args}</span>.
</p>
<p>Any existing file <span class="code">ConfigFile</span> is deleted and a new file
is created when <span class="code">write_config/2</span> is called. The option
<span class="code">append</span> can be used if you wish to add something at the end
of an existing config file, e.g.
<span class="code">ttb:write_config(ConfigFile,What,[append])</span>.
</p>
<h4>Example: History and configuration files</h4>
<p>See the content of the history buffer</p>
<div class="example"><pre>
(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,[]]}}] </pre></div>
<p>Execute an entry from the history buffer:</p>
<div class="example"><pre>
(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}]} </pre></div>
<p>Write the content of the history buffer to a configuration
file:</p>
<div class="example"><pre>
(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,[]]}}] </pre></div>
<p>Extend an existing configuration:</p>
<div class="example"><pre>
(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,[]]}}] </pre></div>
<p>Go back to a previous configuration after stopping Trace Tool
Builder:</p>
<div class="example"><pre>
(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 </pre></div>
<p>Write selected entries from the history buffer to a
configuration file:</p>
<div class="example"><pre>
(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> </pre></div>
<h3><a name="id63279">2.10
Sequential Tracing</a></h3>
<p>To learn what sequential tracing is and how it can be used,
please turn to the reference manual for the
<strong><span class="code">seq_trace</span></strong> module in the <strong><span class="code">kernel</span></strong>
application.
</p>
<p>The support for sequential tracing provided by the Trace Tool
Builder includes </p>
<ul>
<li>Initiation of the system tracer. This is automatically
done when a trace port is started with <span class="code">ttb:tracer/0/1/2</span>
</li>
<li>Creation of match specifications which activates
sequential tracing</li>
</ul>
<p>Starting sequential tracing requires that a tracer has been
started with the <span class="code">ttb:tracer/0/1/2</span> function. Sequential
tracing can then either be started via a trigger function with a
match specification created with <span class="code">ttb:seq_trigger_ms/0/1</span>,
or directly by using the <span class="code">seq_trace</span> module in the
<span class="code">kernel</span> application.
</p>
<h4>Example: Sequential tracing</h4>
<p>In the following example, the function
<span class="code">dbg:get_tracer/0</span> is used as trigger for sequential
tracing:</p>
<div class="example"><pre>
(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(format).
({<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> </pre></div>
<p>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.</p>
<div class="example"><pre>
(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(format).
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> </pre></div>
<p>In both examples above, the <span class="code">seq_trace:reset_trace/0</span>
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.
</p>
<p>All functions in the <span class="code">seq_trace</span> module, except
<span class="code">set_system_tracer/1</span>, can be used after the trace port has
been started with <span class="code">ttb:tracer/0/1/2</span>.
</p>
<h3><a name="id63411">2.11
Example: Multipurpose trace tool</a></h3>
<p>The module <span class="code">multitrace.erl</span> which can be found in the
<span class="code">src</span> 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 <strong><span class="code">multitrace:format/1/2</span></strong>.
</p>
<dl>
<dt><strong><strong><span class="code">multitrace:debug(What)</span></strong></strong></dt>
<dd>Start calltrace on all processes and trace the given
function(s). The format handler used is
<span class="code">multitrace:handle_debug/4</span> which prints each call and
return. <span class="code">What</span> must be an item or a list of items to trace,
given on the format <span class="code">{Module,Function,Arity}</span>,
<span class="code">{Module,Function}</span> or just <span class="code">Module</span>.</dd>
<dt><strong><strong><span class="code">multitrace:gc(Procs)</span></strong></strong></dt>
<dd>Trace garbage collection on the given process(es). The
format handler used is <span class="code">multitrace:handle_gc/4</span> which
prints start and stop and the time spent for each GC.</dd>
<dt><strong><strong><span class="code">multitrace:schedule(Procs)</span></strong></strong></dt>
<dd>Trace in- and out-scheduling on the given process(es). The
format handler used is <span class="code">multitrace:handle_schedule/4</span> 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.</dd>
</dl>
</div>
<div class="footer">
<hr>
<p>Copyright © 2002-2012 Ericsson AB. All Rights Reserved.</p>
</div>
</div>
</div></body>
</html>
distrib
>
Fedora
>
17
>
i386
>
media
>
updates
>
by-pkgid
>
675c8c8167236dfcf8d66da674f931e8
>
files
>
1044
