From 7e3bbc9f57bab238d04545bc0cda70ca0bb0b9f8 Mon Sep 17 00:00:00 2001 From: Piotr Dorobisz Date: Wed, 16 Mar 2011 12:18:12 +0100 Subject: updated documentation --- lib/observer/doc/src/ttb.xml | 229 ++++++++++++++++++++---- lib/observer/doc/src/ttb_ug.xml | 387 ++++++++++++++++++++++++++++++---------- 2 files changed, 485 insertions(+), 131 deletions(-) (limited to 'lib/observer') 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 @@ ttb Siri hansen + Bartłomiej Puzoń 1 - 2002-02-25 + 2010-08-13 PA1 ttb.sgml @@ -42,6 +43,35 @@

When using ttb, dbg shall not be used in parallel.

+ + start_trace(Nodes, Patterns, FlagSpec, Opts) -> Result + Start a trace port on each given node. + + Result = see p/2 + Nodes = see tracer/2 + Patterns = [tuple()] + FlagSpec = {Procs, Flags} + Proc = see p/2 + Flags = see p/2 + Opts = see tracer/2 + + +

This function is a shortcut allowing to start a trace with one command. Each + tuple in Patterns is converted to list which is in turn passed to + ttb:tpl. + The call: +ttb:start_trace([Node, OtherNode], +[{mod, foo, []}, {mod, bar, 2}], +{all, call}, +[{file, File}, {handler,{fun myhandler/4, S}}]) + is equivalent to +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) +

+ + tracer() -> Result This is equivalent to tracer(node()). @@ -49,6 +79,17 @@

This is equivalent to tracer(node()).

 + + tracer(Shortcut) -> Result + Handy shortcuts for common tracing settings + + Shortcut = shell | dbg + + +

shell is equivalent to tracer(node(),[{file, {local, "ttb"}}, shell]).

+

dbg is equivalent to tracer(node(),[{shell, only}]).

+ + tracer(Nodes) -> Result This is equivalent to tracer(Nodes,[]). @@ -62,14 +103,21 @@ Result = {ok, ActivatedNodes} | {error,Reason} Nodes = atom() | [atom()] | all | existing | new - Opts = [Opt] - Opt = {file,Client} | {handler, FormatHandler} | {process_info,PI} + Opts = Opt | [Opt] + Opt = {file,Client} | {handler, FormatHandler} | {process_info,PI} | + shell | {shell, ShellSpec} | {timer, TimerSpec} | {overload, {MSec, Module, Function}} + | {flush, MSec} | resume | {resume, FetchTimeout} + TimerSpec = MSec | {MSec, StopOpts} + MSec = FetchTimeout = integer() + Module = Function = atom() + StopOpts = see stop/2 Client = File | {local, File} File = Filename | Wrap Filename = string() Wrap = {wrap,Filename} | {wrap,Filename,Size,Count} FormatHandler = See format/2 PI = true | false + ShellSpec = true | false | only

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 PI = false. -

+

+

The {shell, ShellSpec} option indicates that the trace messages should + be printed on the console as they are received by the tracing + process. This implies {local, File} trace client. If the ShellSpec + is only (instead of true), no trace logs are stored. +

+

The shell option is a shortcut for {shell, true}.

+

The timer option indicates that the trace should be + automatically stopped after MSec milliseconds. StopOpts + are passed to ttb:stop/2 command if specified (default is []). + Note that the timing is approximate, as delays related to + network communication are always present. The timer starts after + ttb:p/2 is issued, so you can set up your trace patterns before. +

+

The overload_protection option allows to enable overload + checking on the nodes under trace. Module:Function(check) + is performed each MSec milliseconds. If the check returns + true, the tracing is disabled on a given node.
+ Module:Function should be able to handle at least three + atoms: init, check and stop. init and + stop give the user a possibility to initialize and clean + up the check environment.
+ When a node gets overloaded, it is not possible to issue ttb:p + nor any command from the ttb:tp family, as it would lead to + inconsistent tracing state (different trace specifications on + different node). +

+

The flush option periodically flushes all file trace + port clients (see dbg:flush_trace_port/1). When enabled, + the buffers are freed each MSec milliseconds. This option is + not allowed with {file, {local, File}} tracing. +

+

{resume, FetchTimeout} enables the autoresume feature. + Whenever enabled, remote nodes try to reconnect to the controlling node + in case they were restarted. The feature requires runtime_tools + application to be started (so it has to be present in the .boot + scripts if the traced nodes run with embedded erlang). If this is + not possible, resume may be performed manually by starting + runtime_tools remotely using rpc:call/4.
+ ttb tries to fetch all logs from a reconnecting node before + reinitializing the trace. This has to finish within FetchTimeout milliseconds + or is aborted
+ By default, autostart information is stored in a file called + ttb_autostart.bin 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 + ttb_autostart_module environment variable for the runtime_tools + application. The module has to respond to the following API: + + write_config(Data) -> ok + 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. + read_config() -> {ok, Data} | {error, Error} + Retrieve configuration stored with write_config(Data). + delete_config() -> ok + Delete configuration stored with write_config(Data). + Note that after this call any subsequent calls to read_config + must return {error, Error}. + + +

+

The resume option implies the default FetchTimeout, which is + 10 seconds

 @@ -110,7 +221,7 @@

This function sets the given trace flags on the given - processes. + processes. The timestamp flag is always turned on.

Please turn to the Reference manual for module dbg 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.

+

Issuing this command starts the timer for this trace if + timer option was specified with tracer/2. +

@@ -155,6 +269,18 @@ ctpg Clear trace pattern on global function calls +

With tp and tpl one of match specification shortcuts + may be used (example: ttb:tp(foo_module, caller)). The shortcuts are: + + return - for [{'_',[],[{return_trace}]}] + (report the return value) + caller - for [{'_',[],[{message,{caller}}]}] + (report the calling function) + {codestr, Str} - for dbg:fun2ms/1 arguments + passed as strings (example: "fun(_) -> return_trace() end") + + +

@@ -189,7 +315,7 @@ - write_config(ConfigFile,Config,Opt) -> ok | {error,Reason} + write_config(ConfigFile,Config,Opts) -> ok | {error,Reason} Creates a config file. ConfigFile = string() @@ -197,7 +323,8 @@ Mod = atom() Func = atom() Args = [term()] - Opt = [] | [append] + Opts = Opt | [Opt] + Opt = append

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.

-

If Opt is not given or if it is [], +

If Opts is not given or if it is [], ConfigFile is deleted and a new file is created. If - Opt = [append], ConfigFile will not be deleted. + Opts = [append], ConfigFile will not be deleted. The new information will be appended at the end of the file.

 @@ -226,7 +353,9 @@ ConfigFile = string() -

Executes all entries in the given config file.

+

Executes all entries in the given config file. Note that the history + of the last trace is always available in the file named + ttb_last_config.

 @@ -243,6 +372,9 @@

The content of a config file can be listed with list_config/1.

+

Note that the history + of the last trace is always available in the file named + ttb_last_config.

 @@ -334,29 +466,52 @@ - stop(Opts) -> stopped + stop(Opts) -> stopped | {stopped, Dir} Stop tracing and fetch/format logs from all nodes - Opts = [Opt] - Opt = fetch | format + Opts = Opt | [Opt] + Opt = nofetch | {fetch_dir, Dir} | format | {format, FormatOpts} | return + Dir = string() + FormatOpts = see format/2 -

Stops tracing on all nodes. -

-

The fetch 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 +

Stops tracing on all nodes. Logs and + trace information files are sent to the trace control node and stored in a directory named - ttb_upload-Timestamp, where Timestamp is on the + ttb_upload_FileName-Timestamp, where Filename is + the one provided with {file, File} during trace setup + and Timestamp is of the form yyyymmdd-hhmmss. Even logs from nodes on the same machine as the trace control node are moved to this directory. -

+ The history list is saved to a file named ttb_last_config + for further reference (as it will be not longer accessible + through history and configuration management functions (like + ttb:list_history/0). +

+

The nofetch option indicates that trace logs shall not be + collected after tracing is stopped. +

+

The {fetch, Dir} option allows to specify the directory + to fetch the data to. If the directory already exists, an + error is thrown. +

The format option indicates that the trace logs shall be formatted after tracing is stopped. Note that this - option also implies the fetch 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.

+ fetching the logs. All logs in the fetch directory will be merged. + You may use {format, FormatOpts} to pass additional + arguments to format/2.

+

The return option indicates that the return value + should be {stopped, Dir} and not just stopped. + This implies fetch. +

+ + + + get_et_handler() + Returns et handler. + +

The et handler returned by the function may be used with format/2 + or tracer/2. Example: ttb:format(Dir, [{handler, ttb:get_et_handler()}]).

 @@ -372,37 +527,37 @@ File = string() | [string()] 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. - Options = [Opt] - Opt = {out,Out} | {handler,FormatHandler} + Options = Opt | [Opt] + Opt = {out,Out} | {handler,FormatHandler} | disable_sort Out = standard_io | string() - FormatHandler = {Function, InitialState} | et + FormatHandler = {Function, InitialState} Function = fun(Fd,Trace,TraceInfo,State) -> State Fd = standard_io | FileDescriptor This is the file descriptor of the destination file Out Trace = tuple() This is the trace message. Please turn to the Reference manual for the erlangmodule for details. TraceInfo = [{Key,ValueList}] - This includes the keys flags, clientand node, and if handleris given as option to the tracer function, this is also included. In addition all information written with the write_trace_info/2function is included. + This includes the keys flags, client and node, and if handler is given as option to the tracer function, this is also included. In addition all information written with the write_trace_info/2function is included. -

Reads the given binary trace log(s). If a directory or a - list of logs is given and the timestamp flag was set - during tracing, the trace messages from the different logs are - merged according to the timestamps. -

+

Reads the given binary trace log(s). The logs are processed + in the order of their timestamp as long as disable_sort + option is not given. +

If FormatHandler = {Function,InitialState}, Function will be called for each trace message. If - FormatHandler = et, et_viewer in the Event Tracer application (et) is used for presenting the - trace log graphically. ttb provides a few different + FormatHandler = get_et_handler(), et_viewer in + the Event Tracer application (et) is used for presenting + the trace log graphically. ttb provides a few different filters which can be selected from the Filter menu in the et_viewer. If FormatHandler is not given, a default handler is used which presents each trace message as a line of text.

If Out is given, FormatHandler gets the - filedescriptor to Out as the first parameter. + file descriptor to Out as the first parameter.

-

Out is ignored if FormatHandler = et. +

Out is ignored if et format handler is used.

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 @@

- 20022009 + 20022010 Ericsson AB. All Rights Reserved. @@ -48,11 +48,13 @@ Formatting of binary trace logs and merging of logs from multiple nodes. -

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 +

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 dbg 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 dbg directly instead.

@@ -64,14 +66,15 @@ 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:format/1/2 (as long as there is anything to format, of + course).

-

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:tracer/0/1/2 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).

-

ttb:p/2 specifies which processes that shall be - traced. Trace flags given in this call specifies what to trace on +

ttb:p/2 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.

@@ -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.

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 + tracer and for formatting (the custom fetch dir is however provided). + This gives a trace log named Node-ttb in the newly-created + directory, where Node is the name of the node. The default handler prints the formatted trace messages in the shell.

(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 ]]> -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]). ]]>

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. -

+ logs will therefore be fetched to a directory named + ttb_upload_debug_log-YYYYMMDD-HHMMSS +

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 @@ -278,12 +278,156 @@ do_print(Out,{trace_ts,P,return_from,{M,F,A},R,Ts},N) -> 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"}}}]). +(trace_control@durin)1> ttb:tracer(mynode@diskless,{file,{local, +{wrap,"mytrace"}}}). {ok,[mynode@diskless]} +
+ Additional tracing options +

When setting up a trace, several features may be turned on:

+ + time-constrained tracing, + overload protection, + autoresuming. + +
+ Time-constrained tracing +

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 + {timer, TimerSpec} option. If TimerSpec has the + form of MSec, the trace is stopped after MSec + milliseconds using ttb:stop/0. If any additional options + are provided (TimerSpec = {MSec, Opts}), ttb:stop/1 + is called instead with Opts as the arguments. The timer + is started with ttb:p/2, so any trace patterns should + be set up before. ttb:start_trace/4 + always sets up all pattern before invoking ttb:p/2. + 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 +

+(tiger@durin)1>ttb:start_trace([node()], + [{erlang, now,[]}], + {all, call}, + [{timer, {5000, format}}]). + +
+
+ +

When tracing live systems, special care needs to be always taken + not to overload a node with too heavy tracing. ttb provides + the overload option to help to address the problem.

+

{overload, MSec, Module, Function} instructs the ttb backend + (called observer_backend, part of the runtime_tools + application) to perform overload check every MSec milliseconds. + If the check (namely Module:Function(check)) returns + true, tracing is disabled on the selected node.

+

Overload protection activated on one node does not + affect other nodes, where the tracing continues as normal. + ttb:stop/0/1 fetches data from all clients, including everything + that has been collected before overload protection was activated. + Note that + changing trace details (with ttb:p and ttb:tp/tpl...) + 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. +

+

Module:Function provided with the overload option must + handle three calls: init, check and stop. init + and stop allows to perform some setup and teardown required by + the check. An overload check module could look like this (note that + check is always called by the same process, so put and + get are possible). +

+-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. +
+
+ Autoresume +

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, resume has to be used. When + it is, the failing node tries to reconnect + to trace control node as soon as runtime tools is started. + This implies that runtime_tools must be included in + other node's startup chain (if it is not, one could still + resume tracing by starting runtime_tools manually, + i.e. by an RPC call).

+

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 + {resume, MSec}). The data fetched this way is then + merged with all other traces.

+

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 (ttb_autostart_module + environment variable of runtime_tools). Please see the + ttb's reference manual to see the module's API. This example + shows the default handler

+ +-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)). + +

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 {flush, MSec} + as one of ttb:tracer/2 option flushes all buffers + every MSec milliseconds.

+
+
+ dbg mode +

The {shell, ShellType} option allows to make ttb + operation similar to dbg. Using {shell, true} + displays all trace messages in the shell before storing them. + {shell, only} additionally disables message storage + (so that the tool behaves exactly like dbg). This is allowed + only with ip trace ports ({trace, {local, File}}). +

+

The command ttb:tracer(dbg) is a shortcut for the pure-dbg + mode ({shell, only}).

+
+
+
Trace Information and the .ti File @@ -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 - 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. -

+ write_trace_info/2 function. .ti files are always fetched + with other logs when the trace is stopped. +

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 @@ -327,7 +467,12 @@ do_print(Out,{trace_ts,P,return_from,{M,F,A},R,Ts},N) -> 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. -

+

+

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. +

Wrap logs can be formatted one by one or all at once. See Formatting.

@@ -348,12 +493,10 @@ do_print(Out,{trace_ts,P,return_from,{M,F,A},R,Ts},N) -> 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. + binary log(s) to format. This is usually the name of a directory + that ttb created during log fetch. Unless there is the disable_sort + option provided, the logs from different files are always sorted + according to timestamp in traces.

The second argument to ttb:format/2 is a list of options. The out 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 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. + prints each trace message as a line of text. The disable_sort + option indicates that there logs should not be merged according to + timestamp, but processed one file after another (this might be + a bit faster).

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 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 +

The actual trace message is passed as the second argument (Trace). + The possible values of Trace are:

+ + all trace messages described in erlang:trace/3 documentation, + + {drop, N} if ip tracer is used (see dbg:trace_port/2), + + end_of_trace received once when all trace messages have + been processed. + +

By giving the format handler ttb:get_et_handler(), you can have the trace log presented graphically with et_viewer in the Event Tracer application (see Presenting trace logs with Event Tracer). -

+

+

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 format/1/2.

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

Start tracing:

-(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(...) ... @@ -443,7 +603,7 @@ ok to the User's Guide and Reference Manuals for the et application.

-

By giving the format handler et, you can have the +

By giving the format handler ttb:get_et_handler(), 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 @@ -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.

-

As an example this module is used, and the function - bar:f1() is called from another module foo.

+

In the next example, modules foo and bar are used:

+-module(foo). +-export([start/0,go/0]). + +start() -> + spawn(?MODULE, go, []). + +go() -> + receive + stop -> + ok; + go -> + bar:f1(), + go() + end. + -module(bar). -export([f1/0,f3/0]). f1() -> @@ -506,12 +680,23 @@ f1() -> 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: + ok. + +

Now let's set up the trace.

+ +(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()}}). + + +

This shoud render a result similar to the + following:

@@ -520,25 +705,37 @@ f3() -> Filter: "mods_and_procs" + +

Note, that we can use ttb:start_trace/4 function to help + us here:

+ +(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). + +
Automatically collect and format logs from all nodes -

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. +

By default ttb:stop/1 fetches trace logs and + trace information files from all nodes. The logs are stored in a + new directory named ttb_upload-Filename-Timestamp under the working + directory of the trace control node. Fetching may be disabled by + providing the nofetch option to ttb:stop/1. User can + specify a fetch directory of his choice passing the + {fetch_dir, Dir} option.

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. -

+ stopped. +

@@ -546,13 +743,18 @@ f3() ->

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. + tpl, ctp, ctpl and ctpg. There are only + two things added by ttb for these functions: + + 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; + shortcuts are provided for the most common match + specifications (in order not to force the user to use + dbg:fun2ms continually). +

Use list_history/0 to see the content of the history buffer, and run_history/1 to re-execute one of the entries. @@ -574,7 +776,8 @@ f3() -> 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. + entries to write. Moreover, the history buffer is always dumped + to ttb_last_config when ttb:stop/0/1 is called.

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}] -- cgit v1.2.3