tnf tracing is a set of programs and API's that can be used to present a high-level view of the performance of an executable, a library, or part of the kernel. tracing is used to analyze a program's performance and identify the conditions that produced a bug.

The core elements of tracing are:

TNF_PROBE_*(\|)

prex

kernel probes

tnfxtract

tnfdump

libtnfctl

tnf_process_enable()

tnf_process_disable()

tnf_thread_enable()

tnf_thread_disable()

Example 1 Tracing a Process

The following function in some daemon process accepts job requests of various types, queueing them for later execution. There are two "debug probes" and one "production probe." Note that probes which are intended for debugging will not be compiled into the final version of the code; however, production probes are compiled into the final product.

 /*
 * To compile in all probes (for development):
 * cc -DTNF_DEBUG ...
 *
 * To compile in only production probes (for release):
 * cc ...
 *
 * To compile in no probes at all:
 * cc -DNPROBE ...
 */
#include <tnf/probe.h>
void work(long, char *);
enum work_request_type { READ, WRITE, ERASE, UPDATE };
static char *work_request_name[] = {"read", "write", "erase", "update"};
main(\|)
{
 long i;
 for (i = READ; i <= UPDATE; i++)
 work(i, work_request_name[i]);
}
void work(long request_type, char *request_name)
{
 static long q_length;
 TNF_PROBE_2_DEBUG(work_start, "work",
 "XYZ%debug 'in function work'",
 tnf_long, request_type_arg, request_type,
 tnf_string, request_name_arg, request_name);
 /* assume work request is queued for later processing */
 q_length++;
 TNF_PROBE_1(work_queue, "work queue",
 "XYZ%work_load heavy",
 tnf_long, queue_length, q_length);
 TNF_PROBE_0_DEBUG(work_end, "work", "");
}

The production probe "work_queue," which remains compiled in the code, will, when enabled, log the length of the work queue each time a request is received.

The debug probes "work_start" and "work_end, " which are compiled only during the development phase, track entry to and exit from the work() function and measure how much time is spent executing it. Additionally, the debug probe "work_start" logs the value of the two incoming arguments request_type and request_name. The runtime overhead for disabled probes is low enough that one can liberally embed them in the code with little impact on performance.

For debugging, the developer would compile with -DTNF_DEBUG, run the program under control of prex(1), enable the probes of interest (in this case, all probes), continue the program until exit, and dump the trace file:

% cc
-DTNF_DEBUG -o daemon daemon.c # compile in all probes
% prex daemon # run program under prex control
Target process stopped
Type "continue" to resume the target, "help" for help ...
prex> list probes $all # list all probes in program
<probe list output here>
prex> enable $all # enable all probes
prex> continue # let target process execute
<program output here>
prex: target process finished
% ls /tmp/trace-* # trace output is in trace-<pid>
/tmp/trace-4194
% tnfdump /tmp/trace-4194 # get ascii output of trace file
<trace records output here>

For the production version of the system, the developer simply compiles without -DTNF_DEBUG.

Example 2 Tracing the Kernel

Kernel tracing is similar to tracing a process; however, there are some differences. For instance, to trace the kernel, you need superuser privileges. The following example uses prex(1) and traces the probes in the kernel that capture system call information.

Allocate kernel
trace buffer and capture trace data:
root# prex -k
Type "help" for help ...
prex> buffer alloc 2m # allocate kernel trace buffer
Buffer of size 2097152 bytes allocated
prex> list probes $all # list all kernel probes
<probe list output here>
prex> list probes syscall # list syscall probes
 # (keys=syscall)
<syscall probes list output here>
prex> enable syscall # enable only syscall probes
prex> ktrace on # turn on kernel tracing
<Run your application in another window at this point>
prex> ktrace off # turn off kernel tracing
prex> quit # exit prex
Extract the kernel's trace buffer into a file:
root# tnfxtract /tmp/ktrace # extract kernel trace buffer
Reset kernel tracing:
root# prex -k
prex> disable $all # disable all probes
prex> untrace $all # untrace all probes
prex> buffer dealloc # deallocate kernel trace buffer
prex> quit

CAUTION: Do not deallocate the trace buffer until you have extracted it into a trace file. Otherwise, you will lose the trace data that you collected from your experiment!

Examine the kernel trace file:

root# tnfdump /tmp/ktrace # get ascii dump of trace file
<trace records output here>

prex can also attach to a running process, list probes, and perform a variety of other tasks.

See attributes(5) for descriptions of the following attributes:

prex(1), tnfdump(1), tnfxtract(1), TNF_DECLARE_RECORD(3TNF), TNF_PROBE(3TNF), libtnfctl(3TNF), tnf_process_disable(3TNF), tnf_kernel_probes(4), attributes(5)