How TNF Works

The TNF utilities consist of the libtnfprobe library and the prex(1) and tnfdump(1) commands:

• libtnfprobe--A library that is linked to your program and generates trace records to the binary TNF trace file.

• prex--A utility that manipulates the probe points and the kinds of data they gather.

• tnfdump--A utility that converts the binary TNF trace file to an ASCII file.

You insert commands in your code at points (probe points) where you want to collect data. You start running your executable object with prex, which lets you manipulate the probe points. The information collected is written to a trace file in a format called Trace Normal Form (TNF). tnfdump converts the binary TNF trace file to an ASCII file.

You can insert probe points anywhere in C or C⁺⁺ code, including .init() sections, .fini() sections, multithreaded code, shared objects, and shared objects opened by dlopen(3X).

You can also connect functions called probe functions to these probe points. Probe functions perform actions based on the information collected. (Currently, the only available probe function is a debug function that writes output to stderr.)

In a typical TNF session, you do the following:

1. Insert probe points in your programs. (Your source code might already have probe points built into it.)

2. Start your program with prex (this automatically preloads libtnfprobe). (Alternatively, you can link with libtnfprobe when you start your program. If you do this, you can attach prex to the running program. See "Attaching prex to a Running Process".)

3. Manipulate the probe points through prex to gather the information that you want from the program.

4. Convert the binary information trace file produced by the program to an ASCII file with tnfdump. (See "Converting the Binary File to Readable Format".)

5. Examine the information in the ASCII file.

Inserting Probe Points

The details of inserting probe points are covered fully in "Advanced Topics".

"A Sample C Program" shows the design and placement of some probe points. "A Sample prex Session" and "Reading the Trace File" show how probe points are manipulated and what information they provide.

Starting prex

You can either load your program with prex or attach prex to an already running process. The following two sections explain both procedures.

Starting Your Program With prex

When you start your program with prex, it preloads the libtnfprobe library into the target program, so the program does not have to be explicitly linked with libtnfprobe.

prex starts your program running, then stops the program before any user code is executed. Execution is stopped even before the .init() sections are executed, so you can place probe points in the .init() sections to trace initialization code.

In the simplest case, with an executable named a.out that takes no arguments and that contains probe points, the following command can be used:

$ prex a.out

(prex uses the $PATH environment variable to find the executable.)

To specify options, use:

prex [-o outfilename] [-s kbytes_size] 
   [-l sharedobjs] cmd [cmdargs...]

The -o, -s, and -l options are explained in "Command Line Options for prex ".

Attaching prex to a Running Process

If the program named a.out is running and the ps(1) command shows that a.out has a process ID (PID) of 2374, then the following command attaches prex to a.out:

$ prex -p 2374

If you are attaching prex to your already-running program, libtnfprobe must be linked to your program first. If you have not linked with libtnfprobe, prex exits with the error message that libtnfprobe is not linked to your program.

Linking With libtnfprobe

Linking with the library increases the size of your program by about 33 kilobytes (25 kilobytes shareable) and by the size of the trace file that is allocated (controllable through a command line option to prex). If you are never going to attach to a running program using prex, don't link with libtnfprobe.

However, if a program is not easy to restart and is a long-running program that you might someday want to gather information about, then do link with libtnfprobe. A window server is a good example of this--not the sort of program you want to stop and restart often--so you probably want to link with libtnfprobe before you start it running.

You can link with libtnfprobe in one of two ways:

If you are compiling your program, include -ltnfprobe on the cc line (if using -lthread, always put -ltnfprobe before -lthread).

$ cc -ltnfprobe -lthread -o cookie cookie.c

If your program is already compiled or you don't want to build your program with an explicit dependency on libtnfprobe, use the following command:

$ LD_PRELOAD=libtnfprobe.so.1 executable_object_name

See the Linker and Libraries Guide for an explanation of LD_PRELOAD.

Halting and Continuing prex

After you use prex to load the program, or attach prex to a running program, use Control-c to stop your program and pass control to prex.

When you see the prex prompt, prex is running and your program is halted.

prex>

Enter prex commands to control the probe points. For example, you can list probe points, turn on tracing, and debug your program.

To continue running your program, enter the continue command.

prex> continue

To stop your program and return to prex, press Control-c.

$ ^c
prex>

Table 1-1 lists the standard prex command line options.

Command Line Options for prex

Running prex

After you have prex connected to your program, use prex commands to change the parameters of the data to be collected. You can use the prex list command to see all the probes in your program. As your program runs, each time a probe point is executed, information is recorded in the trace file. You look at the collected information with tnfdump(), described in "Reading the tnfdump File".

You can attach and detach prex from your program repeatedly, creating multiple sessions. For example, in your first session you could start the target with prex, set up the probes, and type quit resume.

This will start prex, define the information you want to collect, quit prex, and start collecting information by resuming execution of your program. The commands to do this are shown in Table 1-2.

In a following session, you could attach prex to the same program, reconfigure the probes, and again type continue. You can do this any number of times.

All traces are written to the trace file name specified in the first session --this file name cannot be changed.

Components of the prex Command

The programmer who has inserted the probe points in the source code has assigned various attributes and (optional) values to each probe point. For example, each probe point has a "name" attribute whose value is the name the programmer chose for it.

Look at Table 1-3 for a list of the predefined attributes and the meanings of their values. The prex command lets you select a group of probe points by matching on their attributes or values. You can then trace or debug the selected probe points.

Table 1-5 lists the prex commands and their actions.

In code Example 1-1, the TNF_PROBE macro defines the probe point named work_start. This probe point has two arguments whose values will be logged--state and message. Each time the probe named work_start is encountered, a time stamp and the values of the variables state and message are logged to the trace file.

Example 1-1 prex Attributes and Values

	#include <tnf/probe.h>
	
	int
	work(int state, char *message)
	{
    TNF_PROBE_2(work_start, "work_module work"
               "sunw%debug in function work",
               tnf_long, int_input, state,
               tnf_string, string_input, message);
   ...
   ...
	}

For more information on TNF_PROBE macros, including this example, see "Using the TNF_PROBE Macros".

Table 1-3 lists the predefined attributes.

Attributes

Attributes are characteristics by which you identify probe points in your code. Table 1-3 lists the predefined attributes. You can add more attributes with the TNF_PROBE macros. See "Using the TNF_PROBE Macros".

Grammar for Matching Probes

Select probes based on their attributes and values. The selection specification is called a selector_list. Each attribute or value can be described as one of the following:

• Identifier--a sequence of characters using letters, numbers, and the symbols _\. and % (underscore, backslash, period, and percent). Identifiers cannot begin with a number.

• Quoted string--a sequence of characters in single quotes, taken literally; useful when the string being matched is a reserved word. See Table 1-4 for a list of reserved words.

• Regular expressions--a sequence of characters enclosed in slashes (//); expanded for a match following the rules for ed(1); when slashes occur in the regular expression, as in a path name, escape the slashes with backslashes: /\/tmp\/filename.

A selector_list consists of one or more selector= selector items. If the initial selector= is not provided, it defaults to keys=. For example, the enable command is specified as :

enable selector_list

An example of this command is:

enable name=/first/ file='sampleZ.c'

This enables all probe points with either the name attribute containing the value first (a regular expression match), or the file attribute equal to the value sampleZ.c (Note that the trace is a disjunction and not a conjunction.)

Use $set_name as a shorthand alias for a selector_list specification. In the following example, the set_name is myprobes.

create $myprobes name=/first/ file='sampleZ.c'
enable $myprobes

This does the same thing as the previous example. The set_name follows the identifier naming rules. The $all default set selects all probes in the program.

Reserved Words

Table 1-4 lists the reserved words. Enclose them in single quotes if you use them to select attributes or values.

For example:

enable 'trace'='on'

means enable all probes whose trace attribute has the value of ON. Both trace and on are reserved words, so they both have to be enclosed in single quotation marks.

list name file probes $all

Tracing, Enabling, and Connecting

To trace at a probe point, the probe point must have trace on and it must be enabled. To debug at a probe point, the probe point must be connected to the debug function and must be enabled.

Table 1-6 shows which combinations of tracing, enabling, and connecting result in which actions.

Controlling prex From a Script

Enter commands to prex either from the prex command line or from a file containing prex commands.

When you start prex, it searches for a file named .prexrc first in $HOME/ and next in the directory from which you started prex. Commands are read from all files that are found. Therefore it is possible to have a .prexrc file in the current directory that overrides defaults that are set up by the .prexrc file in the home directory.

After reading any .prexrc files that are found, input is expected from the prex command line. To set up an experiment entirely using .prexrc files, the last statement in it can be quit resume, which quits prex but lets your program resume.

Also, when prex is running you can use the source filename command to specify a file from which prex reads commands. This file can have any name you like.

As with commands entered from the prex command line, all commands in the script should be in ASCII. The following rules apply:

• Terminate each command with the newline character.

• Continue a command onto the next line by ending the previous line with a backslash (\) character.

• Separate tokens by white space (one or more spaces or tabs).

• Start comments with a hash mark (#).

  While the command language is the same for prex commands entered from the command line and for commands from a script, commands that return output (such as list probes...) make little sense in a script because the output goes to stdout.

A Sample C Program

This program, cookie.c, asks for a cookie. The response must be entered in uppercase, or it is incorrect. You can also find the prime factor of a number. In the process of doing these two things, you can see how the trace function works.

To compile this program and get an executable called cookie(), use

$ cc -o cookie cookie.c 

Five probe points are defined (and highlighted) in this program. They are named start (line 17), inloop (line 33), factor_start (line 60), found_a_factor (line 65), and factor_end (line 72). More information about these probe points is gathered and explained in "A Sample prex Session".

Example 1-2 Code for cookie.c()

#include <sys/types.h>
#include <stdio.h>
#include <string.h>
#include <tnf/probe.h>

#define MAX_RESPONSE_SIZE	256

static void find_factor(int n);

int
main(int argc, char **argv)
{
    boolean_t	shouldexit = B_FALSE;
    int 	sum = 0, max_loop = 5;
    int		i;

    TNF_PROBE_0(start, "cookie main", 
         "sunw%debug starting main");

    while (!shouldexit) {
	      char	response[MAX_RESPONSE_SIZE];
	      int	factor_input;

      	(void) printf("give me a COOKIE! ");
	      (void) scanf("%s", response);

      	if (!strcmp(response, "COOKIE")) {
	           (void) printf("thanks!\n");
	           shouldexit = B_TRUE;
      	}

      	else if (!strcmp(response, "loop")) {
       	    for (i = 0; i < max_loop; i++) {
	             	TNF_PROBE_2(inloop, "cookie main
                           loop","sunw%debug in the loop",
			                       	tnf_long, loop_count, 	i,
		                       		tnf_long, total_iterations, 	sum);
             		sum++;
           	}
	         		max_loop += 2 ;
     		}

	    	else if (!strcmp(response, "factor")) {
         			(void) printf("number you want factored? ");
	         		(void) scanf("%d", &factor_input);
	         		find_factor(factor_input);
    		}

	    	else {
	         		(void) printf("not a %s, ", response);
		    }
    }
    return 0;

}   /* end main */
static void
find_factor(int n)
{
    int i;

    (void) printf("\tfactors of %d = ", n);
    TNF_PROBE_1(factor_start, "factor", "",
      		tnf_long, input_number, n);

    for (i=2; i <= n; i++) {
      		while (n % i == 0) {
		        	TNF_PROBE_2(found_a_factor, "cookie find_factor",
               "", tnf_long, searching_for, n,
	           			tnf_long, factor, i);
	        		(void) printf("%d ", i);
	        		n /= i;
      		}
    }
    TNF_PROBE_0(factor_end, "factor", "");
    (void) printf("\n");
}

A Sample prex Session

This sample of a prex session is designed to show the different capabilities of prex. The data collected when cookie is run is shown in "Reading the tnfdump File".

% prex cookie     /* prex is loading the executable cookie. */
Target process stopped
Type "continue" to resume the target, "help" for help ...
prex> list sets
$all      'keys'=/.*/    /* One set is defined--$all 
                            (which is all the probes). */
prex> list fcns
&debug    tnf_probe_debug      /* The debug function is 
                                  the only one available. */
prex> list probes $all
name=inloop enable=off trace=on file=cookie.c line=35 funcs=<no value>
name=factor_end enable=off trace=on file=cookie.c line=72 funcs=<no value>
name=factor_start enable=off trace=on file=cookie.c line=61 funcs=<no value>
name=found_a_factor enable=off trace=on file=cookie.c line=67 funcs=<no value>
name=start enable=off trace=on file=cookie.c line=17 funcs=<no value>
prex>/*  The line number shows the end of each of the five probes. */
prex> create $factor /factor/    /* Create a new set that
                            matches any probe whose "keys" */
prex>       /* attribute contains the string "factor". */
prex> list sets
$all      'keys'=/.*/
$factor   'keys'=/factor/        
/* A new set named "factor" 
                                   is created and now shows
                                   up in */
prex>                              
  /* the list of sets. */
prex> list probes $factor            
/* This line tells you which probes matched the set
$factor.*/
name=factor_end enable=off trace=on file=cookie.c line=72 funcs=<no value>
name=factor_start enable=off trace=on file=cookie.c line=61 funcs=<no value>
name=found_a_factor enable=off trace=on file=cookie.c line=67 funcs=<no value>
prex> list probes $all          /* Check to see if any 
                                 probes are enabled. */
name=inloop enable=off trace=on file=cookie.c line=35 funcs=<no value>
name=factor_end enable=off trace=on file=cookie.c line=72 funcs=<no value>
name=factor_start enable=off trace=on file=cookie.c line=61 funcs=<no value>
name=found_a_factor enable=off trace=on file=cookie.c line=67 funcs=<no value>
name=start enable=off trace=on file=cookie.c line=17 funcs=<no value>
prex>                  /* None are enabled, 
                      but all have trace on. */

prex> enable $all             /* Enable all the probes.*/
prex> list probes $all        /* Check again to see if any 
                              probes are enabled. */  
name=inloop enable=on trace=on file=cookie.c line=35 funcs=<no value>
name=factor_end enable=on trace=on file=cookie.c line=72 funcs=<no value>
name=factor_start enable=on trace=on file=cookie.c line=61 funcs=<no value>
name=found_a_factor enable=on trace=on file=cookie.c line=67 funcs=<no value>
name=start enable=on trace=on file=cookie.c line=17 funcs=<no value
prex> list values name              /* Find out what the probe names are. */
name =                              
	   factor_end                   
	   factor_start
	   found_a_factor
	   inloop
	   start
prex> list values /.*/          /* List all predefined
                              attributes with their values. */
enable =              /* Only unique attributes are listed.*/
    on 
file =
	   cookie.c
funcs =
	  
keys =
	   cookie
	   factor
	   find_factor
	   loop
	   main
line =
	   17
	   35
	   61
	   67
	   72
name =
	   factor_end
	   factor_start
	   found_a_factor
	   inloop
	   start
object =
	   cookie
slots =
	   factor
	   input_number
	   loop_count
	   searching_for
	   total_iterations
sunw%debug =           /* The user-defined macro, sunw%debug, 
                       is also listed. */
	   in     /* This macro is defined in line 17 of cookie.c. */
	   loop
	   main
	   starting
	   the
trace =
	   on
prex> list values object
object =
	   cookie
prex> connect &debug name=inloop
prex> list /.*/ probes $all         /* List all the
                           information about all the probes */
enable=on trace=on object=cookie funcs=<no value> name=inloop slots=loop_count
total_iterations keys=cookie main loop file=cookie.c line=35 sunw%debug=in the loop 
enable=on trace=on object=cookie funcs=<no value> name=factor_end slots=<no value>
keys=factor file=cookie.c line=72
enable=on trace=on object=cookie funcs=<no value> name=factor_start slots=input_number
keys=factor file=cookie.c line=61 
enable=on trace=on object=cookie funcs=<no value> name=found_a_factor slots=searching_for
factor keys=cookie find_factor file=cookie.c line=67 
enable=on trace=on object=cookie funcs=<no value> name=start slots=<no value> keys=cookie
main file=cookie.c line=17 sunw%debug=starting main 
prex> continue
give me a COOKIE! loop       
 /* An example of loop counts*/
probe inloop; sunw%debug "in the loop"; loop_count=0; total_iterations=0;
probe inloop; sunw%debug "in the loop"; loop_count=1; total_iterations=1;
probe inloop; sunw%debug "in the loop"; loop_count=2; total_iterations=2;
probe inloop; sunw%debug "in the loop"; loop_count=3; total_iterations=3;
probe inloop; sunw%debug "in the loop"; loop_count=4; total_iterations=4;
give me a COOKIE! factor	
number you want factored? 25
	factors of 25 = 5 5
give me a COOKIE! factor
number you want factored? 43645729
	factors of 43645729 = 43645729
give me a COOKIE! ^C Target process stopped
Type "continue" to resume the target, "help" for help...
prex> continue
give me a COOKIE! biscuit
not a biscuit, give me a COOKIE!  cookie
not a cookie, give me a COOKIE! COOKIE
thanks!
prex: target process finished

Reading the Trace File

The binary trace file you create with prex contains information determined by the prex commands you chose (see "Running prex").

By default, this file is created in /$TMPDIR/trace-pid, where pid is the process ID of the target program. If $TMPDIR is not set, the file is created in /tmp/trace-pid. You can override these default locations with the -o option to the prex command (see "Command Line Options for prex " for a full explanation).

When the trace file has been filled, newer events overwrite the older events. The default size of a trace file is four megabytes. This can be changed with the -s option for prex.

After a program is tracing to a file, there is no way to clear the trace file or to give it a different name for the lifetime of that program. If you disconnect from the target and attach later with a different trace file name, the newer name is ignored.

Converting the Binary File to Readable Format

To convert the binary trace file to an ASCII file, use the tnfdump command and the name of the binary trace file. Because tnfdump output goes to stdout by default, you probably want to redirect it into a file.

$ tnfdump filename > newfile

The- -r option to tnfdump provides detailed (raw) TNF output. Reading this output requires an understanding of TNF that is beyond the scope of this chapter.

Reading the tnfdump File

The following table shows output from the prex cookie command described in "A Sample prex Session". The output of the tnfdump file is very wide--open a very wide window to display it:

probe	 tnf_name: "start" tnf_string: "keys cookie main;file cookie.c;line 17;sunw%debug
starting main"
probe	 tnf_name: "factor_start" tnf_string: "keys factor;file cookie.c;line 61;"
probe	 tnf_name: "found_a_factor" tnf_string: "keys cookie find_factor;file cookie.c;line
67;"
probe	 tnf_name: "factor_end" tnf_string: "keys factor;file cookie.c;line 72;"
---------------- ---------------- ----- ----- ---------- --- -------------------------
------------------------
    Elapsed (ms)  Delta (ms)     PID  LWPID  TID  CPU Probe Name        Data / Description . . .
---------------- ---------------- ----- ----- ---------- --- -------------------------
------------------------
	 0.000000	0.000000	5354	1	0	- start	
	4551.625000	4551.625000	5354	1	0	- factor_start	input_number: 25
	4571.278000	19.653000	5354	1	0	- found_a_factor	searching_for: 25 factor: 5
	4571.543000	0.265000	5354	1	0	- found_a_factor	searching_for: 5 factor: 5
	4571.732000	0.189000	5354	1	0	- factor_end	
	 23151.434000	18579.702000	5354	1	0	- factor_start	input_number: 101247
	 23151.509000	0.075000	5354	1	0	- found_a_factor	searching_for: 101247 factor: 3
	 23228.090000	76.581000	5354	1	0	- found_a_factor	searching_for: 33749 factor: 33749
	 23228.250000	0.160000	5354	1	0	- factor_end	
	 89041.868000	65813.618000	5354	1	0	- factor_start	input_number: -1690908149
	 89041.920000	0.052000	5354	1	0	- factor_end	
	108271.852000	19229.932000	5354	1	0	- factor_start	input_number: 43645729
	208857.756000	 100585.904000	5354	1	0	- found_a_factor	searching_for: 43645729 factor:
43645729
	208857.960000	0.204000	5354	1	0	- factor_end	
	334511.548000	 125653.588000	5354	1	0	- factor_start	input_number: 12
	334511.618000	0.070000	5354	1	0	- found_a_factor	searching_for: 12 factor: 2
	334511.689000	0.071000	5354	1	0	- found_a_factor	searching_for: 6 factor: 2
	334511.750000	0.061000	5354	1	0	- found_a_factor	searching_for: 3 factor: 3
	334511.808000	0.058000	5354	1	0	- factor_end	

Looking at the tnfdump display, you can see how long it takes to find a factor by subtracting the factor_start time from the factor_end time. Factoring 43645729 took 208857.960000 - 108271.852000, or 100586.11 milliseconds. Factoring 12 took 334511.808000 - 334511.548000, or .260000 milliseconds.

Results are reported with nanosecond precision for all hardware platforms. Accuracy, however, depends on the hardware platform used.