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.