Skip to content

Your first TRACE

Jump to bottom
Eric Flumerfelt edited this page Jun 17, 2022 · 1 revision

Your first TRACE

Actually, your first TRACE and TLOG…
Consider the following command:

export TRACE_DIR=<root_where_include/trace.h_exists>
cat <<EOF | g++ -I$TRACE_DIR/include -o simple -xc++ -
#include "TRACE/trace.h"
int main(void)
{
    TLOG(TLVL_INFO)<<"hello 1st"; // C++
    for(int ii=0; ii<4; ++ii)
        TRACE(TLVL_DEBUG, "hello 2nd"); // C/linux kernel compatible
    return 0;
}
EOF

The above should produce ./simple:

./simple

The output should be (except with appropriate date values):

09-30 19:51:13.684724 <stdin>     INFO main(): hello 1st

By default, “DEBUG” is disabled.
The default output has, in addition to the “message” in the TRACE or TLOG macro invocations (e.g. “hello 1st”),
the timestamp, the “trace id” and the “trace level” (which is the 1st parameter in the macro).
DEBUG can be easily enabled by one of two ways:

  1. TRACE_LVLS environment variable, e.g. export TRACE_LVLS=–1
  2. tonS combined with an environment variable that enables “fast memory file” tracing.

The output if fully configurable via the TRACE_TIME_FMT and TRACE_PRINT environment variables:
i.e. TRACE_TIME_FMT=“%Y~~%b~~%d %H:%M:S,%03d” TRACE_PRINT=“%T %L [%0F at %f:%u] %M”.

2020-Sep-30 19:52:50,415 INFO [main() at <stdin>:4] hello 1st
2020-Sep-30 19:52:50,415 DEBUG [main at <stdin>:6] hello 2nd
2020-Sep-30 19:52:50,415 DEBUG [main at <stdin>:6] hello 2nd
2020-Sep-30 19:52:50,415 DEBUG [main at <stdin>:6] hello 2nd
2020-Sep-30 19:52:50,415 DEBUG [main at <stdin>:6] hello 2nd

High speed memory logging can be enabled via: export TRACE_NAME=TRACE
With the slow path (stdout) DEBUG disabled (unset TRACE_LVLS), the memory traces can be seen with the “tshow” utility which is include with the TRACE package.
tshow is often used with the tdelta utility which is also included with the TRACE package.

Now

./simple

again produces

2020-Sep-30 19:59:58,421 INFO [main() at <stdin>:4] hello 1st

tshow | tdelta shows:

idx                      us_tod       delta     pid     tid cpu trcname lvl msg                     
--- --------------------------- ----------- ------- ------- --- ------- --- ------------------------
  0 2020-Sep-30 19:59:58,421295           0  430408  430408   1   TRACE DBG main at hello 2nd
  1 2020-Sep-30 19:59:58,421294           1  430408  430408   1   TRACE DBG main at hello 2nd
  2 2020-Sep-30 19:59:58,421293           1  430408  430408   1   TRACE DBG main at hello 2nd
  3 2020-Sep-30 19:59:58,421291           2  430408  430408   1   TRACE DBG main at hello 2nd
  4 2020-Sep-30 19:59:58,421146         145  430408  430408   1   TRACE NFO main at hello 1st

The above (tshow defaults to reverse chronological order) shows 145 usec between the 1st “INFO” log
and the 1st DBG message. The next set of DBG messages are recorded in about 1 microsecond. The
reason for the difference is that the 1st (INFO) message is recorded in the memory file and then
formatted and sent to stdout via a write system call.

See source:trunk/doc/quick-start.txt and/or source:trunk/doc/
users_guide.txt for further information.

Clone this wiki locally