diff options
Diffstat (limited to 'lib')
| -rw-r--r-- | lib/observer/doc/src/ttb.xml | 229 | ||||
| -rw-r--r-- | lib/observer/doc/src/ttb_ug.xml | 387 |
2 files changed, 485 insertions, 131 deletions
diff --git a/lib/observer/doc/src/ttb.xml b/lib/observer/doc/src/ttb.xml index fcaa1c2504..8531be93e3 100644 --- a/lib/observer/doc/src/ttb.xml +++ b/lib/observer/doc/src/ttb.xml @@ -25,11 +25,12 @@ <title>ttb</title> <prepared>Siri hansen</prepared> + <prepared>Bartłomiej Puzoń</prepared> <responsible></responsible> <docno>1</docno> <approved></approved> <checked></checked> - <date>2002-02-25</date> + <date>2010-08-13</date> <rev>PA1</rev> <file>ttb.sgml</file> </header> @@ -43,6 +44,35 @@ </description> <funcs> <func> + <name>start_trace(Nodes, Patterns, FlagSpec, Opts) -> Result</name> + <fsummary>Start a trace port on each given node.</fsummary> + <type> + <v>Result = see p/2</v> + <v>Nodes = see tracer/2</v> + <v>Patterns = [tuple()]</v> + <v>FlagSpec = {Procs, Flags}</v> + <v>Proc = see p/2</v> + <v>Flags = see p/2</v> + <v>Opts = see tracer/2</v> + </type> + <desc> + <p>This function is a shortcut allowing to start a trace with one command. Each + tuple in <c>Patterns</c> is converted to list which is in turn passed to + <c>ttb:tpl</c>. + The call:<code type="none"> +ttb:start_trace([Node, OtherNode], +[{mod, foo, []}, {mod, bar, 2}], +{all, call}, +[{file, File}, {handler,{fun myhandler/4, S}}])</code> + is equivalent to <code type="none"> +ttb:start_trace([Node, OtherNode], [{file, File}, {handler,{fun myhandler/4, S}}]), +ttb:tpl(mod, foo, []), +ttb:tpl(mod, bar, 2, []), +ttb:p(all, call)</code> + </p> + </desc> + </func> + <func> <name>tracer() -> Result</name> <fsummary>This is equivalent to tracer(node()).</fsummary> <desc> @@ -50,6 +80,17 @@ </desc> </func> <func> + <name>tracer(Shortcut) -> Result</name> + <fsummary>Handy shortcuts for common tracing settings</fsummary> + <type> + <v>Shortcut = shell | dbg</v> + </type> + <desc> + <p><c>shell</c> is equivalent to <c>tracer(node(),[{file, {local, "ttb"}}, shell])</c>.</p> + <p><c>dbg</c> is equivalent to <c>tracer(node(),[{shell, only}])</c>.</p> + </desc> + </func> + <func> <name>tracer(Nodes) -> Result</name> <fsummary>This is equivalent to tracer(Nodes,[]).</fsummary> <desc> @@ -62,14 +103,21 @@ <type> <v>Result = {ok, ActivatedNodes} | {error,Reason}</v> <v>Nodes = atom() | [atom()] | all | existing | new</v> - <v>Opts = [Opt]</v> - <v>Opt = {file,Client} | {handler, FormatHandler} | {process_info,PI}</v> + <v>Opts = Opt | [Opt]</v> + <v>Opt = {file,Client} | {handler, FormatHandler} | {process_info,PI} | + shell | {shell, ShellSpec} | {timer, TimerSpec} | {overload, {MSec, Module, Function}} + | {flush, MSec} | resume | {resume, FetchTimeout}</v> + <v>TimerSpec = MSec | {MSec, StopOpts}</v> + <v>MSec = FetchTimeout = integer()</v> + <v>Module = Function = atom() </v> + <v>StopOpts = see stop/2</v> <v>Client = File | {local, File}</v> <v>File = Filename | Wrap</v> <v>Filename = string()</v> <v>Wrap = {wrap,Filename} | {wrap,Filename,Size,Count}</v> <v>FormatHandler = See format/2</v> <v>PI = true | false </v> + <v>ShellSpec = true | false | only</v> </type> <desc> <p>This function starts a file trace port on all given nodes @@ -96,7 +144,70 @@ is the process' registered name its globally registered name, or its initial function. It is possible to turn off this functionality by setting <c>PI = false</c>. - </p> + </p> + <p>The <c>{shell, ShellSpec}</c> option indicates that the trace messages should + be printed on the console as they are received by the tracing + process. This implies <c>{local, File}</c> trace client. If the ShellSpec + is <c>only</c> (instead of <c>true</c>), no trace logs are stored. + </p> + <p>The <c>shell</c> option is a shortcut for <c>{shell, true}</c>.</p> + <p>The <c>timer</c> option indicates that the trace should be + automatically stopped after <c>MSec</c> milliseconds. <c>StopOpts</c> + are passed to <c>ttb:stop/2</c> command if specified (default is <c>[]</c>). + Note that the timing is approximate, as delays related to + network communication are always present. The timer starts after + <c>ttb:p/2</c> is issued, so you can set up your trace patterns before. + </p> + <p>The <c>overload_protection</c> option allows to enable overload + checking on the nodes under trace. <c>Module:Function(check)</c> + is performed each <c>MSec</c> milliseconds. If the check returns + <c>true</c>, the tracing is disabled on a given node.<br/> + <c>Module:Function</c> should be able to handle at least three + atoms: <c>init</c>, <c>check</c> and <c>stop</c>. <c>init</c> and + <c>stop</c> give the user a possibility to initialize and clean + up the check environment.<br/> + When a node gets overloaded, it is not possible to issue <c>ttb:p</c> + nor any command from the <c>ttb:tp</c> family, as it would lead to + inconsistent tracing state (different trace specifications on + different node). + </p> + <p>The <c>flush</c> option periodically flushes all file trace + port clients (see <c>dbg:flush_trace_port/1</c>). When enabled, + the buffers are freed each <c>MSec</c> milliseconds. This option is + not allowed with <c>{file, {local, File}}</c> tracing. + </p> + <p><c>{resume, FetchTimeout}</c> enables the autoresume feature. + Whenever enabled, remote nodes try to reconnect to the controlling node + in case they were restarted. The feature requires <c>runtime_tools</c> + application to be started (so it has to be present in the <c>.boot</c> + scripts if the traced nodes run with embedded erlang). If this is + not possible, resume may be performed manually by starting + <c>runtime_tools</c> remotely using <c>rpc:call/4</c>.<br/> + <c>ttb</c> tries to fetch all logs from a reconnecting node before + reinitializing the trace. This has to finish within FetchTimeout milliseconds + or is aborted<br/> + By default, autostart information is stored in a file called + <c>ttb_autostart.bin</c> on each node. If this is not desired + (i.e. on diskless nodes), a custom module to handle autostart + information storage and retrieval can be provided by specifying + <c>ttb_autostart_module</c> environment variable for the <c>runtime_tools</c> + application. The module has to respond to the following API: + <taglist> + <tag><c>write_config(Data) -> ok</c></tag> + <item>Store the provided data for further retrieval. It is + important to realize that the data storage used must not + be affected by the node crash.</item> + <tag><c>read_config() -> {ok, Data} | {error, Error}</c></tag> + <item>Retrieve configuration stored with <c>write_config(Data)</c>.</item> + <tag><c>delete_config() -> ok</c></tag> + <item>Delete configuration stored with <c>write_config(Data)</c>. + Note that after this call any subsequent calls to <c>read_config</c> + must return <c>{error, Error}</c>. + </item> + </taglist> + </p> + <p>The <c>resume</c> option implies the default <c>FetchTimeout</c>, which is + 10 seconds</p> </desc> </func> <func> @@ -110,7 +221,7 @@ </type> <desc> <p>This function sets the given trace flags on the given - processes. + processes. The <c>timestamp</c> flag is always turned on. </p> <p>Please turn to the Reference manual for module <c>dbg</c> for details about the possible trace flags. The parameter @@ -119,6 +230,9 @@ registered names or process identifiers. If a registered name is given, the flags are set on processes with this name on all active nodes.</p> + <p>Issuing this command starts the timer for this trace if + <c>timer</c> option was specified with <c>tracer/2</c>. + </p> </desc> </func> <func> @@ -155,6 +269,18 @@ <tag><c>ctpg</c></tag> <item>Clear trace pattern on global function calls</item> </taglist> + <p>With <c>tp</c> and <c>tpl</c> one of match specification shortcuts + may be used (example: <c>ttb:tp(foo_module, caller)</c>). The shortcuts are: + <taglist> + <item><c>return</c> - for <c>[{'_',[],[{return_trace}]}]</c> + (report the return value)</item> + <item><c>caller</c> - for <c>[{'_',[],[{message,{caller}}]}]</c> + (report the calling function)</item> + <item><c>{codestr, Str}</c> - for <c>dbg:fun2ms/1</c> arguments + passed as strings (example: <c>"fun(_) -> return_trace() end"</c>) + </item> + </taglist> + </p> </desc> </func> <func> @@ -189,7 +315,7 @@ </desc> </func> <func> - <name>write_config(ConfigFile,Config,Opt) -> ok | {error,Reason}</name> + <name>write_config(ConfigFile,Config,Opts) -> ok | {error,Reason}</name> <fsummary>Creates a config file.</fsummary> <type> <v>ConfigFile = string()</v> @@ -197,7 +323,8 @@ <v>Mod = atom()</v> <v>Func = atom()</v> <v>Args = [term()]</v> - <v>Opt = [] | [append]</v> + <v>Opts = Opt | [Opt]</v> + <v>Opt = append</v> </type> <desc> <p>This function creates or extends a config file which can be @@ -213,9 +340,9 @@ should be a list of integers pointing out the entries to be stored. </p> - <p>If <c>Opt</c> is not given or if it is <c>[]</c>, + <p>If <c>Opts</c> is not given or if it is <c>[]</c>, <c>ConfigFile</c> is deleted and a new file is created. If - <c>Opt = [append]</c>, <c>ConfigFile</c> will not be deleted. + <c>Opts = [append]</c>, <c>ConfigFile</c> will not be deleted. The new information will be appended at the end of the file.</p> </desc> </func> @@ -226,7 +353,9 @@ <v>ConfigFile = string()</v> </type> <desc> - <p>Executes all entries in the given config file.</p> + <p>Executes all entries in the given config file. Note that the history + of the last trace is always available in the file named + <c>ttb_last_config</c>.</p> </desc> </func> <func> @@ -243,6 +372,9 @@ </p> <p>The content of a config file can be listed with <c>list_config/1</c>.</p> + <p> Note that the history + of the last trace is always available in the file named + <c>ttb_last_config</c>.</p> </desc> </func> <func> @@ -334,29 +466,52 @@ </desc> </func> <func> - <name>stop(Opts) -> stopped</name> + <name>stop(Opts) -> stopped | {stopped, Dir}</name> <fsummary>Stop tracing and fetch/format logs from all nodes</fsummary> <type> - <v>Opts = [Opt]</v> - <v>Opt = fetch | format</v> + <v>Opts = Opt | [Opt]</v> + <v>Opt = nofetch | {fetch_dir, Dir} | format | {format, FormatOpts} | return</v> + <v>Dir = string()</v> + <v>FormatOpts = see format/2</v> </type> <desc> - <p>Stops tracing on all nodes. - </p> - <p>The <c>fetch</c> option indicates that trace logs shall be - collected from all nodes after tracing is stopped. This option - is useful if nodes on remote machines are traced. Logs and - trace information files are then sent to the trace control + <p>Stops tracing on all nodes. Logs and + trace information files are sent to the trace control node and stored in a directory named - <c>ttb_upload-Timestamp</c>, where <c>Timestamp</c> is on the + <c>ttb_upload_FileName-Timestamp</c>, where <c>Filename</c> is + the one provided with <c>{file, File}</c> during trace setup + and <c>Timestamp</c> is of the form <c>yyyymmdd-hhmmss</c>. Even logs from nodes on the same machine as the trace control node are moved to this directory. - </p> + The history list is saved to a file named <c>ttb_last_config</c> + for further reference (as it will be not longer accessible + through history and configuration management functions (like + <c>ttb:list_history/0</c>). + </p> + <p>The <c>nofetch</c> option indicates that trace logs shall not be + collected after tracing is stopped. + </p> + <p>The <c>{fetch, Dir}</c> option allows to specify the directory + to fetch the data to. If the directory already exists, an + error is thrown. + </p> <p>The <c>format</c> option indicates that the trace logs shall be formatted after tracing is stopped. Note that this - option also implies the <c>fetch</c> option, i.e. logs are - collected in a new directory on the trace control node before - formatting. All logs in the directory will be merged.</p> + fetching the logs. All logs in the fetch directory will be merged. + You may use <c>{format, FormatOpts}</c> to pass additional + arguments to <c>format/2</c>.</p> + <p>The <c>return</c> option indicates that the return value + should be <c>{stopped, Dir}</c> and not just <c>stopped</c>. + This implies <c>fetch</c>. + </p> + </desc> + </func> + <func> + <name>get_et_handler()</name> + <fsummary>Returns <c>et</c> handler.</fsummary> + <desc> + <p>The <c>et</c> handler returned by the function may be used with <c>format/2</c> + or <c>tracer/2</c>. Example: <c>ttb:format(Dir, [{handler, ttb:get_et_handler()}])</c>.</p> </desc> </func> <func> @@ -372,37 +527,37 @@ <type> <v>File = string() | [string()]</v> <d>This can be the name of a binary log, a list of such logs or the name of a directory containing one or more binary logs.</d> - <v>Options = [Opt]</v> - <v>Opt = {out,Out} | {handler,FormatHandler}</v> + <v>Options = Opt | [Opt]</v> + <v>Opt = {out,Out} | {handler,FormatHandler} | disable_sort</v> <v>Out = standard_io | string()</v> - <v>FormatHandler = {Function, InitialState} | et</v> + <v>FormatHandler = {Function, InitialState}</v> <v>Function = fun(Fd,Trace,TraceInfo,State) -> State</v> <v>Fd = standard_io | FileDescriptor</v> <d>This is the file descriptor of the destination file <c>Out</c></d> <v>Trace = tuple()</v> <d>This is the trace message. Please turn to the Reference manual for the <c>erlang</c>module for details.</d> <v>TraceInfo = [{Key,ValueList}]</v> - <d>This includes the keys <c>flags</c>, <c>client</c>and <c>node</c>, and if <c>handler</c>is given as option to the tracer function, this is also included. In addition all information written with the <c>write_trace_info/2</c>function is included. </d> + <d>This includes the keys <c>flags</c>, <c>client</c> and <c>node</c>, and if <c>handler</c> is given as option to the tracer function, this is also included. In addition all information written with the <c>write_trace_info/2</c>function is included. </d> </type> <desc> - <p>Reads the given binary trace log(s). If a directory or a - list of logs is given and the <c>timestamp</c> flag was set - during tracing, the trace messages from the different logs are - merged according to the timestamps. - </p> + <p>Reads the given binary trace log(s). The logs are processed + in the order of their timestamp as long as <c>disable_sort</c> + option is not given. + </p> <p>If <c>FormatHandler = {Function,InitialState}</c>, <c>Function</c> will be called for each trace message. If - <c>FormatHandler = et</c>, <c>et_viewer</c> in the <em>Event Tracer</em> application (<c>et</c>) is used for presenting the - trace log graphically. <c>ttb</c> provides a few different + <c>FormatHandler = get_et_handler()</c>, <c>et_viewer</c> in + the <em>Event Tracer</em> application (<c>et</c>) is used for presenting + the trace log graphically. <c>ttb</c> provides a few different filters which can be selected from the Filter menu in the <c>et_viewer</c>. If <c>FormatHandler</c> is not given, a default handler is used which presents each trace message as a line of text. </p> <p>If <c>Out</c> is given, <c>FormatHandler</c> gets the - filedescriptor to <c>Out</c> as the first parameter. + file descriptor to <c>Out</c> as the first parameter. </p> - <p><c>Out</c> is ignored if <c>FormatHandler = et</c>. + <p><c>Out</c> is ignored if <c>et</c> format handler is used. </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 diff --git a/lib/observer/doc/src/ttb_ug.xml b/lib/observer/doc/src/ttb_ug.xml index 44b7b08fd3..7079e88232 100644 --- a/lib/observer/doc/src/ttb_ug.xml +++ b/lib/observer/doc/src/ttb_ug.xml @@ -4,7 +4,7 @@ <chapter> <header> <copyright> - <year>2002</year><year>2009</year> + <year>2002</year><year>2010</year> <holder>Ericsson AB. All Rights Reserved.</holder> </copyright> <legalnotice> @@ -48,11 +48,13 @@ <item>Formatting of binary trace logs and merging of logs from multiple nodes.</item> </list> - <p>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 + <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 <c>dbg</c> 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 <c>dbg</c> directly instead.</p> </section> @@ -64,14 +66,15 @@ trace flags on the processes you want to trace with <c>ttb:p/2</c>. Then, when the tracing is completed, you must stop the tracer with <c>ttb:stop/0/1</c> and format the trace log with - <c>ttb:format/1/2</c>. + <c>ttb:format/1/2</c> (as long as there is anything to format, of + course). </p> - <p><c>ttb:tracer/0/1/2</c> 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). + <p><c>ttb:tracer/0/1/2</c> 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><c>ttb:p/2</c> specifies which processes that shall be - traced. Trace flags given in this call specifies what to trace on + <p><c>ttb:p/2</c> 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> @@ -105,14 +108,15 @@ -export([f/0]). f() -> receive - From when pid(From) -> + From when is_pid(From) -> Now = erlang:now(), From ! {self(),Now} end. </code> <p>The following example shows the basic use of <c>ttb</c> from the erlang shell. Default options are used both for starting the - tracer and for formatting. This gives a trace log named - <c>Node-ttb</c>, where <c>Node</c> is the name of the node. The + tracer and for formatting (the custom fetch dir is however provided). + This gives a trace log named <c>Node-ttb</c> in the newly-created + directory, where <c>Node</c> is the name of the node. The default handler prints the formatted trace messages in the shell.</p> <code type="none"><![CDATA[ @@ -131,11 +135,11 @@ f() -> (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). +(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 @@ -145,11 +149,11 @@ f() -> (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)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("tiger@durin-ttb"). +(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} @@ -167,10 +171,6 @@ ok ]]></code> -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 @@ -180,28 +180,28 @@ start() -> %% 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]). + %% 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 atom(M) -> +trc(M) when is_atom(M) -> trc({M,'_','_'}); -trc({M,F}) when atom(M), atom(F) -> +trc({M,F}) when is_atom(M), is_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! +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(File) -> - ttb:format(File). +format(Dir) -> + ttb:format(Dir). %%% Stop the "mydebug" tool stop() -> - ttb:stop(). + ttb:stop(return). %%% --------Internal functions-------- %%% ---------------------------------- @@ -226,9 +226,9 @@ do_print(Out,{trace_ts,P,return_from,{M,F,A},R,Ts},N) -> [N,Ts,P,M,F,A,R]). ]]></code> <p>To distinguish trace logs produced with this tool from other logs, the <c>file</c> option is used in <c>tracer/2</c>. The - logs will therefore be named <c>Node-debug_log</c>, where - <c>Node</c> is the name of the node where the log is produced. - </p> + logs will therefore be fetched to a directory named + <c>ttb_upload_debug_log-YYYYMMDD-HHMMSS</c> + </p> <p>By using the <c>handler</c> option when starting the tracer, the information about how to format the file is stored in the trace information file (<c>.ti</c>). This is not necessary, as @@ -278,13 +278,157 @@ do_print(Out,{trace_ts,P,return_from,{M,F,A},R,Ts},N) -> must be given to the <c>tracer/2</c> function with the value <c>{local, File}</c>, e.g.</p> <code type="none"> -(trace_control@durin)1> ttb:tracer(mynode@diskless,[{file,{local, -{wrap,"mytrace"}}}]). +(trace_control@durin)1> ttb:tracer(mynode@diskless,{file,{local, +{wrap,"mytrace"}}}). {ok,[mynode@diskless]} </code> </section> </section> <section> + <title>Additional tracing options</title> + <p>When setting up a trace, several features may be turned on:</p> + <list type="bulleted"> + <item>time-constrained tracing,</item> + <item>overload protection,</item> + <item>autoresuming.</item> + </list> + <section> + <title>Time-constrained tracing</title> + <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 + <c>{timer, TimerSpec}</c> option. If <c>TimerSpec</c> has the + form of <c>MSec</c>, the trace is stopped after <c>MSec</c> + milliseconds using <c>ttb:stop/0</c>. If any additional options + are provided (<c>TimerSpec = {MSec, Opts}</c>), <c>ttb:stop/1</c> + is called instead with <c>Opts</c> as the arguments. The timer + is started with <c>ttb:p/2</c>, so any trace patterns should + be set up before. <c>ttb:start_trace/4</c> + always sets up all pattern before invoking <c>ttb:p/2</c>. + 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><code> +(tiger@durin)1>ttb:start_trace([node()], + [{erlang, now,[]}], + {all, call}, + [{timer, {5000, format}}]). +</code> + </section> + <section> + <label>Overload protection</label> + <p>When tracing live systems, special care needs to be always taken + not to overload a node with too heavy tracing. <c>ttb</c> provides + the <c>overload</c> option to help to address the problem.</p> + <p><c>{overload, MSec, Module, Function}</c> instructs the ttb backend + (called <c>observer_backend</c>, part of the <c>runtime_tools</c> + application) to perform overload check every <c>MSec</c> milliseconds. + If the check (namely <c>Module:Function(check)</c>) returns + <c>true</c>, 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. + <c>ttb:stop/0/1</c> fetches data from all clients, including everything + that has been collected before overload protection was activated. + Note that + changing trace details (with <c>ttb:p</c> and <c>ttb:tp/tpl...</c>) + 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><c>Module:Function</c> provided with the <c>overload</c> option must + handle three calls: <c>init</c>, <c>check</c> and <c>stop</c>. <c>init</c> + and <c>stop</c> allows to perform some setup and teardown required by + the check. An overload check module could look like this (note that + <c>check</c> is always called by the same process, so <c>put</c> and + <c>get</c> are possible). + </p><code> +-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.</code> + </section> + <section> + <title>Autoresume</title> + <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, <c>resume</c> has to be used. When + it is, the failing node tries to reconnect + to trace control node as soon as <c>runtime tools</c> is started. + This implies that <c>runtime_tools</c> must be included in + other node's startup chain (if it is not, one could still + resume tracing by starting <c>runtime_tools</c> 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 + <c>{resume, MSec}</c>). 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 (<c>ttb_autostart_module</c> + environment variable of <c>runtime_tools</c>). Please see the + ttb's reference manual to see the module's API. This example + shows the default handler</p> + <code> +-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)). + </code> + <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 <c>{flush, MSec}</c> + as one of <c>ttb:tracer/2</c> option flushes all buffers + every <c>MSec</c> milliseconds.</p> + </section> + <section> + <title>dbg mode</title> + <p>The <c>{shell, ShellType}</c> option allows to make <c>ttb</c> + operation similar to <c>dbg</c>. Using <c>{shell, true}</c> + displays all trace messages in the shell before storing them. + <c>{shell, only}</c> additionally disables message storage + (so that the tool behaves exactly like dbg). This is allowed + only with ip trace ports (<c>{trace, {local, File}}</c>). + </p> + <p>The command <c>ttb:tracer(dbg)</c> is a shortcut for the pure-dbg + mode (<c>{shell, only}</c>).</p> + </section> + </section> + + <section> <marker id="trace_info"></marker> <title>Trace Information and the .ti File</title> <p>In addition to the trace log file(s), a file with the extension @@ -292,13 +436,9 @@ do_print(Out,{trace_ts,P,return_from,{M,F,A},R,Ts},N) -> 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 - <c>write_trace_info/2</c> function. - </p> - <p>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 <c>.ti</c>. - </p> + <c>write_trace_info/2</c> 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 <c>TI</c> parameter is a list of @@ -327,7 +467,12 @@ do_print(Out,{trace_ts,P,return_from,{M,F,A},R,Ts},N) -> each log. <c>ttb</c> 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> + <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 <seealso marker="#format">Formatting</seealso>. </p> @@ -348,12 +493,10 @@ do_print(Out,{trace_ts,P,return_from,{M,F,A},R,Ts},N) -> present the trace log graphically (see <seealso marker="#et_viewer">Presenting trace logs with Event Tracer</seealso>). </p> <p>The first argument to <c>ttb:format/1/2</c> 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 <c>timestamp</c> flag was set when tracing, the trace - messages from the different logs will be merged according to the - timestamps in each message. + binary log(s) to format. This is usually the name of a directory + that ttb created during log fetch. Unless there is the <c>disable_sort</c> + option provided, the logs from different files are always sorted + according to timestamp in traces. </p> <p>The second argument to <c>ttb:format/2</c> is a list of options. The <c>out</c> option specifies the destination where the @@ -363,7 +506,10 @@ do_print(Out,{trace_ts,P,return_from,{M,F,A},R,Ts},N) -> option is not given, the <c>handler</c> option given when starting the tracer is used. If the <c>handler</c> option was not given when starting the tracer either, a default handler is used, which - prints each trace message as a line of text. + prints each trace message as a line of text. The <c>disable_sort</c> + 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 @@ -396,10 +542,24 @@ end </code> <c>handle_gc/4</c> in the module <c>multitrace.erl</c> which can be found in the <c>src</c> directory of the Observer application. </p> - <p>By giving the format handler <c>et</c>, you can have the trace + <p>The actual trace message is passed as the second argument (<c>Trace</c>). + The possible values of <c>Trace</c> are:</p> + <list type="bulleted"> + <item>all trace messages described in <c>erlang:trace/3</c> documentation, + </item> + <item><c>{drop, N}</c> if ip tracer is used (see <c>dbg:trace_port/2</c>), + </item> + <item><c>end_of_trace</c> received once when all trace messages have + been processed.</item> + </list> + <p>By giving the format handler <c>ttb:get_et_handler()</c>, you can have the trace log presented graphically with <c>et_viewer</c> in the Event Tracer application (see <seealso marker="#et_viewer">Presenting trace logs with Event Tracer</seealso>). - </p> + </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 <c>format/1/2</c>.</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 '*' @@ -407,7 +567,7 @@ end </code> </p> <p>Start tracing:</p> <code type="none"> -(tiger@durin)1> ttb:tracer(node(),[{file,{wrap,"trace"}}]). +(tiger@durin)1> ttb:tracer(node(),{file,{wrap,"trace"}}). {ok,[tiger@durin]} (tiger@durin)2> ttb:p(...) ... </code> @@ -443,7 +603,7 @@ ok to the User's Guide and Reference Manuals for the <c>et</c> application. </p> - <p>By giving the format handler <c>et</c>, you can have the + <p>By giving the format handler <c>ttb:get_et_handler()</c>, you can have the trace log presented graphically with <c>et_viewer</c> in the Event Tracer application. <c>ttb</c> provides a few different filters which can be selected from the Filter menu in the @@ -495,9 +655,23 @@ ok filters respectively, except that each module or function can have several vertical lines, one for each process it resides on. </p> - <p>As an example this module is used, and the function - <c>bar:f1()</c> is called from another module <c>foo</c>.</p> + <p>In the next example, modules <c>foo</c> and <c>bar</c> are used:</p> <code type="none"> +-module(foo). +-export([start/0,go/0]). + +start() -> + spawn(?MODULE, go, []). + +go() -> + receive + stop -> + ok; + go -> + bar:f1(), + go() + end. +</code><code type="none"> -module(bar). -export([f1/0,f3/0]). f1() -> @@ -506,12 +680,23 @@ f1() -> f2() -> spawn(?MODULE,f3,[]). f3() -> - ok. </code> - <p>The <c>call</c> and <c>return_to</c> flags are used, and - trace pattern is set on local calls in module <c>bar</c>. - </p> - <p><c>ttb:format("tiger@durin-ttb", [{handler, et}])</c> gives the - following result: + ok.</code> + + <p>Now let's set up the trace.</p> +<code> +(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()}}). +</code> + + <p>This shoud render a result similar to the + following: </p> <p></p> <image file="et_processes.gif"> @@ -520,25 +705,37 @@ f3() -> <image file="et_modsprocs.gif"> <icaption>Filter: "mods_and_procs"</icaption> </image> + + <p>Note, that we can use <c>ttb:start_trace/4</c> function to help + us here:</p> +<code> +(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). +</code> + </section> </section> <section> <marker id="fetch_format"></marker> <title>Automatically collect and format logs from all nodes</title> - <p>If the option <c>fetch</c> is given to the <c>ttb:stop/1</c> - 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 <c>ttb_upload-Timestamp</c> under the working - directory of the trace control node. + <p>By default <c>ttb:stop/1</c> fetches trace logs and + trace information files from all nodes. The logs are stored in a + new directory named <c>ttb_upload-Filename-Timestamp</c> under the working + directory of the trace control node. Fetching may be disabled by + providing the <c>nofetch</c> option to <c>ttb:stop/1</c>. User can + specify a fetch directory of his choice passing the + <c>{fetch_dir, Dir}</c> option. </p> <p>If the option <c>format</c> is given to <c>ttb:stop/1</c>, the trace logs are automatically formatted after tracing is - stopped. Note that <c>format</c> also implies <c>fetch</c>, - i.e. the trace logs will be collected from all nodes as for the - <c>fetch</c> option before they are formatted. All logs in the - upload directory are merged during formatting. - </p> + stopped. + </p> </section> <section> @@ -546,13 +743,18 @@ f3() -> <p>For the tracing functionality, <c>dbg</c> could be used instead of the <c>ttb</c> for setting trace flags on processes and trace patterns for call trace, i.e. the functions <c>p</c>, <c>tp</c>, - <c>tpl</c>, <c>ctp</c>, <c>ctpl</c> and <c>ctpg</c>. The only - thing added by <c>ttb</c> 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 <c>ttb</c> from the erlang - shell. + <c>tpl</c>, <c>ctp</c>, <c>ctpl</c> and <c>ctpg</c>. There are only + two things added by <c>ttb</c> for these functions: + <list type="bulleted"> + <item>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 <c>ttb</c> from the erlang shell;</item> + <item>shortcuts are provided for the most common match + specifications (in order not to force the user to use + <c>dbg:fun2ms</c> continually</item>). + </list> </p> <p>Use <c>list_history/0</c> to see the content of the history buffer, and <c>run_history/1</c> to re-execute one of the entries. @@ -574,7 +776,8 @@ f3() -> selected entries from the history by calling <c>ttb:write_config(ConfigFile,NumList)</c>, where <c>NumList</c> is a list of integers pointing out the history - entries to write. + entries to write. Moreover, the history buffer is always dumped + to <c>ttb_last_config</c> when <c>ttb:stop/0/1</c> is called. </p> <p>User defined entries can also be written to a config file by calling the function @@ -720,9 +923,7 @@ ok {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"). +(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}} @@ -743,9 +944,7 @@ ok (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"). +(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}] |