Prerequisite assumptions:
   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.
   $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.
The macro takes a _level_ (integer from 0-63),
a _format_spec_ (or message) and arguments as specified by the
format_spec.


When the executable is run, trace will attempt to initialize.
in order for trace to be "activated" within the executable,
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.
The env.vars. are:
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
0x0000000000000001 for the M (mmap file entries), and 0x0 for both
the S (stdout) and T (trigger) masks.

LEVELMASKS:

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 0x0000000000000001 0x0000000000000000 0x0000000000000000
199          _TRACE_ 0x0000000000000001 0x0000000000000000 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). 


CONVENIENCE FUNCTIONS

In general, the functions support a -f<file> and/or -n<name> option.
tdelta, however, has different options.

tinfo [opt]        -- print info
tshow [opt]        -- show the buffer (pipe to pager, head or tail)
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 S destination
tonS [opt] <lvls>  -- turns levels on (and also the mode) for the M 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"



TRACE SHOW

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(0,"hello %u sts=%d",ii,sts);
        TRACE(1,"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 0,1
   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=1 ./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


Advanced TRACEing - OS interaction
----------------------------------
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.

Once the modules is loaded, other modules can be developed/loaded which
contain TRACEs.
