-
Notifications
You must be signed in to change notification settings - Fork 1
TRACE Users Guide
{{toc}}
trace software is at $TRACE_DIR, shell is bash,
the approriate bin dir (ie. $TRACE_DIR/Linux+2.6-2.12/bin) has
been added to PATH along with $TRACE_DIR/script.
If “ups” has not been used to “setup TRACE”,
$TRACE_DIR/script/trace.sh.functions has been source to put
“convenience” functions in the environment.
TRACING capability is added to an executable by including the
$TRACE_DIR/include/trace.h file and sprinkling TRACE() macros
at significant/interesting or otherwise appropriate locations
in the code.
TRACEs allow the “messages” to go either or both of two destinations:
- circular memory buffer (aka “fast” destination) or
- stdout (or other fd) (aka “slow” destination).
By default (unless one of six TRACE_* env.vars. is set), only the
fast path is activated.
The TRACE macro takes a level (integer from 0-63),
a format_spec (or message) and optional arguments as specified by
the
format_spec.
The TLOG (lvl) streamer macro also takes a leve (integer from 0-63).
There are predefined enums for the lower values: TLVL_ERROR,
TLVL_WARNING, TLVL_INFO, etc.
The levels correspond to bits in a 64 bit bit mask and by default, only
the lower levels,
associated with TLVL_INFO and below are enabled by default (or
initially).
First example:
cat <<EOF | g++ -I$TRACE_DIR/include -xc++ - -oexample && ./example
#include "trace.h"
int main(){
TLOG(TLVL_INFO)<<"hello world";
TRACE(TLVL_INFO,"hello world");
return(0);
}
EOF
should produce:
10-06 20:24:07.995145 <stdin> INFO main(): hello world
10-06 20:24:07.995186 <stdin> INFO main: hello world
The default output includes: timestamp, “facility” (), severity (INFO), and message.
The default output can be changed via the TRACE_TIME_FMT and TRACE_PRINT
env.vars
and the whole “slow” destination can be changed via a MACRO
(TRACE_USER_FUNCTION) redefinition.
$TRACE_DIR/include/tracemf.h is an example of changing the slow
destination
to use the messagefacility: in which case, depending upon
messagefacility
configuration, the ouput could look like:
%MSG-i TRACE: simple_example 08-Nov-2017 01:44:35 CST
hello world
%MSG
When the executable is run, trace will attempt to initialize.
In order for trace to be “activated” to write the “fast” circular memory
buffer,
one or more of the 6 TRACE environment variables must be defined.
They can be defined in the environment or by the program itself
(before
the first TRACE or TRACE_CNTRL macro is encountered. Actually, there
are two TRACE_CNTRL’s which can cause a re-initialization, but more on
that later.
TRACE_FILE -- location of the trace file to be used (created if it does
not exist) -- the default is /tmp/trace_buffer_$USER
TRACE_NAME -- "TRACE NAME" for the program (more on this later) --
the default is "TRACE"
TRACE_MSGMAX -- the max bytes of _format_spec_ that will be saved --
default 128.
TRACE_ARGSMAX -- the max number of parameter that will be saved --
default 10.
TRACE_NUMENTS -- the number of entries in the buffer -- default 50000
TRACE_NAMTBLENTS -- the number of different possible trace names (including
a special one which is used if all the other entries are
used) -- default 20.
The last four are used when a file is created. Once the file is
create,
the parameters cannot be changed — delete the file or use a different
one.
Note: I have only tested what I believe are reasonable values for the
last
env.vars.
The trace_cntl program can be used to create the file. For example, one
could
do:
rm -f /tmp/trace_buffer_$USER; TRACE_NAMTBLENTS=200 tinfo
The following should be printed:
trace_initialized =1
mode =0x1
writeIdxCount =0x00000000 entries used: 0
largestMultiple =0xffffbc70
trigIdxCnt =0x00000000
triggered =0
trigActivePost =0
traceLevel =0x0000000000000001 0x0000000000000000
num_entries =50000
max_msg_sz =128 includes system inforced terminator
max_params =10
entry_size =256
namLvlTbl_ents =200
namLvlTbl_name_sz =16
wrIdxCnt offset =0x2000
namLvls offset =0x2080
buffer_offset =0x4000
memlen =12820480
Notice “namLvlTbl_ents =200”
When the file is first created, the default for all the “level masks”
is
0x0000000000000003 for the M (circular “memory” queue) and S (stdout or
“slow”) entry masks and
0x0 for T (trigger) mask.
TRACE allows C stringstream formatting of messages using the TRACEN_ or
TRACE_ macros.
Using these macros, one can format strings and numbers into a message
before it is sent to
either memory or a non-memory destination (i.e stdout, cout, or file,
etc.).
TRACE_( 15, "number of bytes is " << bytes << " from " << driver_name );
In a similar manor TRACE also allows for C std::string formatting.
TRACE( 15, "number of bytes is "+std::to_string(bytes) + " from " + driver_name );
TRACE( 15, "number of bytes is %d from " + driver_name, bytes );
TLOG(15) << "Message with arg" << arg
This example show that the conversion of bytes to ascii can be delayed.
This can be a significant
efficiency if the message is going only to memory. When a message is
destined for other than memory,
delayed formatting cannot occur.
| write syscall | mem copy | |
| formatted | slower | faster |
| delayed formatting | n/a | fastest |
When a log message goes to both memory and any non-memory destination,
the bulk of the time
will be spent sending to the non-memory destination
There are basically two main set of masks: one to cause a trace to
be saved into the circulare memory buffer (file) and one to cause a
trace to be printed to stdout.
The masks can be view via the “ttids” function which will cause, for
example the following to be printed:
TID NAME maskM maskS maskT
--- ---------------- ------------------ ------------------ ------------------
198 TRACE 0x0000000000000003 0x0000000000000003 0x0000000000000000
199 _TRACE_ 0x0000000000000003 0x0000000000000003 0x0000000000000000
In order for a TRACE to reach it’s desination, the bit in the
mask which corresponds to the level (0-63) specified in TRACE must
be
set in the mask for the specified TID (which will correspond to the
TRACE_NAME unless all the entries have been used by other names).
With the above printout, only trace level 0 TRACEs with some up only
in the trace file — shown via the “tshow” function.
Additional NAMEs (TIDs) will be created when the name specified by
TRACE_NAME
does not exist (until the maximum configured NAMEs is reached in which
case
the name TRACE will be used).
Note: when different NAMEs are used, TRACEs in header files may then
be
associated with multiple NAMEs. If your application uses TRACEs in
header
files and multiple NAMEs/TIDs, you may wish to use a specific level
range
(i.e. 12-19) for the TRACEs in the header files and then
activate/deactivate them globally (for all TIDs).
In general, the functions support a -f and/or -n option.
tdelta, however, has different options.
tinfo [opt] -- print info
tshow [opt] -- show the buffer (pipe to pager, head or tail)
tlvls, ttids [opt] -- show the TID, names, masks
tlvlM [opt] <msk> -- set the mask -- often -n<name> is helpful
tlvlS [opt] <msk> -- set the mask -- often -n<name> is helpful
tlvlT [opt] <msk> -- set the mask -- often -n<name> is helpful
tmodeM [opt] <0|1> -- disable (0) or enable (1) the memory destination
tmodeS [opt] <0|1> -- disable (0) or enable (1) the stdout destination
tfreeze [opt] -- turns memory destination off -- "freezes" contents
treset [opt] -- clears the memory buffer and trigger parameters
tonM [opt] <lvls> -- turns levels on (and also the mode) for the M destination
tonS [opt] <lvls> -- turns levels on (and also the mode) for the S destination
toffS [opt]<lvls> -- turns both the stdout and memory desinations off
toffM [opt]<lvls> -- turns both the stdout and memory desinations off
tdelta [opts] -- trace_delta.pl "$@" | less
tcntl [opt] -- general -- give cmd to trace_cntl i.e: tcntl TRACE 0 "hi"
Note: adding a “g” to tonM, tonS, toffM, or toffS will effect all
currently defined trace names/ids.
For example, tonMg 0-63 would turn on all memory tracing.
Perhaps the most significant part of TRACE is sending TRACEs to memory.
Consider the example program compile to ./simple:
cat <<'EOF' | g++ -Wall -x c++ -I$TRACE_DIR/include -o simple -
#include "trace.h"
int main(void)
{
int sts=setenv("TRACE_LVLS","-1",0);
for (unsigned ii; ii<250000; ++ii) {
TRACE(2,"hello %u sts=%d",ii,sts);
TRACE(3,"hello %u sts=%d",ii,sts);
}
return 0;
}
EOF
And then the following “time commands”:
1. time env -i ./simple | wc -l
2. TRACE_MSGMAX=0 tonM 2,3
time env -i LOGNAME=$LOGNAME TRACE_MSGMAX=0 TRACE_LVLS= ./simple | wc -l
3. time env -i LOGNAME=$LOGNAME TRACE_MSGMAX=0 ./simple | wc -l
The first should send 500,000 “messages” to stdout. The second should
send 500,000 messages to a memory mapped trace_buffer file
(/tmp/trace_buffer_).
The 3rd command should send the messages to both memory and stdout.
Note: “wc -l” is used to count the message send to stdout in these
examples.
A 4th command to time:
4. time env -i USER=$USER TRACE_MSGMAX=0 TRACE_LVLS=0x4 ./simple | wc -l
will send 500000 message to memory, but only half (250,000) to stdout.
In real applications, TRACE can be configured to send many messages to
memory and a relatively small number to stdout.
Note: As noted above, TRACE is controlled through the environment and
also
through the buffer file, when enabled. The use of “env -i” in the
examples
above is simple to ensure a consistent environment for these examples.
Normally, the environment variables are configure separately/initially.
At this point there should be a trace_buffer file with the message in
it.
To see them, do:
export TRACE_MSGMAX=0
tshow
To see timing between each message, pipe the output from tshow into tdelta:
tshow | tdelta
An example of the output would be:
$ tshow | tdelta | head
idx us_tod delta tsc tid TID cpu lv r msg
----- ---------------- --------- ---------- ----- --- --- -- - -----------------------------
0 1454954308853479 0 468018178 15812 18 19 1 . hello 249999 sts=0
1 1454954308853479 0 468017834 15812 18 19 0 . hello 249999 sts=0
2 1454954308853479 0 468017438 15812 18 19 1 . hello 249998 sts=0
3 1454954308853479 0 468017002 15812 18 19 0 . hello 249998 sts=0
4 1454954308853478 1 468016650 15812 18 19 1 . hello 249997 sts=0
5 1454954308853478 0 468016298 15812 18 19 0 . hello 249997 sts=0
6 1454954308853478 0 468015946 15812 18 19 1 . hello 249996 sts=0
7 1454954308853478 0 468015602 15812 18 19 0 . hello 249996 sts=0
In the output above, the first column “idx” is just a simple line
index.
“us_tod” is the unix time in microseconds since Jan 1, 1970; “delta”
is
the delta microseconds between the current line and the previous line;
“tsc” is the 32 bit “time stamp counter register” value — it usually
counts
at the clock frequency of the processor (typically some number of GHz);
“tid”
is the unix OS task id; “TID” is the TRACE NAME ID; “cpu” is the core;
“lv”
is the TRACE level (1st parameter to TRACE macro); “r” is, if not “.”,
the
number of retries that occurred when getting the trace “slot” index; and
“msg”
(the rest of the line) is the message.
The output can be controlled via the option env.var. TRACE_SHOW. For,
example,
to omit the “tsc”:
$ TRACE_SHOW=HxNTiICLR tshow | tdelta | head
idx us_tod delta tid TID cpu lv r msg
----- ---------------- --------- ----- --- --- -- - -----------------------------
0 1454954308853479 0 15812 18 19 1 . hello 249999 sts=0
1 1454954308853479 0 15812 18 19 0 . hello 249999 sts=0
2 1454954308853479 0 15812 18 19 1 . hello 249998 sts=0
3 1454954308853479 0 15812 18 19 0 . hello 249998 sts=0
4 1454954308853478 1 15812 18 19 1 . hello 249997 sts=0
5 1454954308853478 0 15812 18 19 0 . hello 249997 sts=0
6 1454954308853478 0 15812 18 19 1 . hello 249996 sts=0
7 1454954308853478 0 15812 18 19 0 . hello 249996 sts=0
tdelta can convert the time to human readable format:
(Note: when converting the time (via -ct 1), the “-d 1” option needs to
be
specified to tele which column to do the delta on.)
$ export TRACE_SHOW=HxNTiICLR
$ tshow | tdelta -ct 1 -d 1 | head
idx us_tod delta tid TID cpu lv r msg
----- ---------------- --------- ----- --- --- -- - -----------------------------
0 02-08 11:58:28.853479 0 15812 18 19 1 . hello 249999 sts=0
1 02-08 11:58:28.853479 0 15812 18 19 0 . hello 249999 sts=0
2 02-08 11:58:28.853479 0 15812 18 19 1 . hello 249998 sts=0
3 02-08 11:58:28.853479 0 15812 18 19 0 . hello 249998 sts=0
4 02-08 11:58:28.853478 1 15812 18 19 1 . hello 249997 sts=0
5 02-08 11:58:28.853478 0 15812 18 19 0 . hello 249997 sts=0
6 02-08 11:58:28.853478 0 15812 18 19 1 . hello 249996 sts=0
7 02-08 11:58:28.853478 0 15812 18 19 0 . hello 249996 sts=0
Standard unix filtering, (e.g. via grep) can be used and times between
the
remaining lines can be displayed:
$ tshow | grep '1 . hello 24..00' | tdelta -ct 1 -d 1 | head
198 02-08 11:58:28.853447 0 15812 18 19 1 . hello 249900 sts=0
398 02-08 11:58:28.853414 33 15812 18 19 1 . hello 249800 sts=0
598 02-08 11:58:28.853381 33 15812 18 19 1 . hello 249700 sts=0
798 02-08 11:58:28.853348 33 15812 18 19 1 . hello 249600 sts=0
998 02-08 11:58:28.853315 33 15812 18 19 1 . hello 249500 sts=0
1198 02-08 11:58:28.853279 36 15812 18 19 1 . hello 249400 sts=0
1398 02-08 11:58:28.853241 38 15812 18 19 1 . hello 249300 sts=0
1598 02-08 11:58:28.853206 35 15812 18 19 1 . hello 249200 sts=0
1798 02-08 11:58:28.853170 36 15812 18 19 1 . hello 249100 sts=0
1998 02-08 11:58:28.853137 33 15812 18 19 1 . hello 249000 sts=0
TLOG(15) << "message with arg" << std::to_string(arg);
Delayed formatting is significant. However, it is implemented by
inserting C printf style “%” format specifiers and
there is no checking for them in any of the C stream strings - whether
constant or from variable. So, them following
will be will produce unexpected tshow results:
std::string ss("happens to have a %percent and %p is a C printf format specifier");
TLOG(15) << "message " << ss << " with arg" << arg;
This usually is not an issue, but there are several solutions.
Add a “format now” flag to TLOG:
std::string ss("happens to have a %percent and %p is a C printf format specifier");
TLOG(15,1) << "message " << ss << " with arg" << arg;
This will, however, as expected, cause the trace to be less efficient.
A TRACE module can be compiled and loading into the kernel.
The module creates a virtual trace buffer file at /proc/trace/buffer.
export TRACE_FILE=/proc/trace/buffer
A TRACE_NAME “KERNEL” is created. The following levels, if enabled,
with
trace the indicated events:
level event
----- -----
25 system call enter
26 system call exit/return
27 software irq enter
28 software irq return
29 hardware irq enter
30 hardware irq return
31 schedule switch hook
Module load parameters can be used to control aspects of the virtual
trace file.
/root
SL7x :^| treset;tmodeM 1;tcntl TRACE 2 "hello from pid=%d" $$;tfreeze
11-14 00:29:30.746972 TRACE inf hello from pid=11861
--2017-11-14_00:29:30--
/root
SL7x :^| tshow|tdelta -d 1 -ct 1 -syscall /usr/include/asm/unistd_64.h | egrep -C5 'us_tod|hello'
idx us_tod delta pid tid cpu name lvl r msg
--- ---------------- --------- ----- ----- --- ------- --- - -----------------------------
0 11-14 00:29:30.752964 0 13771 13771 3 KERNEL d26 . sys_exit: cpu=3 syscall=gettid(186) ret=0x35cb (13771)
1 11-14 00:29:30.752958 6 13771 13771 3 KERNEL d25 . sysenter: cpu=3 syscall=gettid(186)
2 11-14 00:29:30.752944 14 13771 13771 3 KERNEL d26 . sys_exit: cpu=3 syscall=close(3) ret=0x0 (0)
3 11-14 00:29:30.752939 5 13771 13771 3 KERNEL d25 . sysenter: cpu=3 syscall=close(3)
--
462 11-14 00:29:30.747000 11 0 0 1 KERNEL d31 . schedule: cpu=1 prev=0 next=9
463 11-14 00:29:30.746994 6 0 0 1 KERNEL d28 . sirqexit: cpu=1 vec_nr=1
464 11-14 00:29:30.746987 7 0 0 2 KERNEL d28 . sirqexit: cpu=2 vec_nr=1
465 11-14 00:29:30.746985 2 0 0 1 KERNEL d27 . sirqenter: cpu=1 vec_nr=1
466 11-14 00:29:30.746982 3 0 0 2 KERNEL d27 . sirqenter: cpu=2 vec_nr=1
467 11-14 00:29:30.746972 10 13770 13770 3 TRACE inf . hello from pid=11861
468 11-14 00:29:30.746956 16 13770 13770 3 KERNEL d26 . sys_exit: cpu=3 syscall=gettid(186) ret=0x35ca (13770)
469 11-14 00:29:30.746952 4 13770 13770 3 KERNEL d25 . sysenter: cpu=3 syscall=gettid(186)
470 11-14 00:29:30.746938 14 13770 13770 3 KERNEL d26 . sys_exit: cpu=3 syscall=close(3) ret=0x0 (0)
471 11-14 00:29:30.746933 5 13770 13770 3 KERNEL d25 . sysenter: cpu=3 syscall=close(3)
472 11-14 00:29:30.746924 9 13770 13770 3 KERNEL d28 . sirqexit: cpu=3 vec_nr=7
--2017-11-14_00:30:23--
Once the modules is loaded, other modules can be developed/loaded
which
contain TRACEs.
TRACE includes 3 mode words, “Memory”, “Slow”, and “Trigger”. The “Trigger” mode word can be used to automatically halt TRACE-to-memory after a message is received on a trigger-enabled level.
This behavior can be configured using the following three trace_cntl variables: trigIdxCnt, triggered, trigActivePost.
Calling tcntl trig 4 will enable triggering, and set trigActivePost to
4 (i.e. print the 3 messages after the triggering message before halting
Memory TRACEs). To re-enable memory, call tmodeM 1.
Once TRACE has been triggered, the trigIdxCnt will contain the slot in the buffer of the triggering message, and triggered will be 1. trigActivePost will reflect the number of “after trigger” messages remaining.