Performance Profiling Using TNF

Print-friendly Version

Introduction

Performance improvement is a necessary part of most software development efforts. For all but the smallest of projects, resources must be focused on those areas most likely to yield the greatest improvement for the effort expended. In the Solaris environment, one of the tools available to help identify these areas is the TNF (Trace Normal Form) facility. Using TNF, the program (or programs) whose performance is to be improved is executed and the resulting data is examined to identify which paths are the most likely performance bottlenecks or hot spots.

For most users, collecting TNF data, while not a trivial task, is relatively straightforward. Less obvious is how to analyze the resulting data. The Solaris TNF facility provides only a simple file dump utility to examine the data. Anything resembling data analysis is left to the user. The common approach is to write shell scripts to parse and analyze the file dump output. This article describes the use of two unbundled tools, TNFView and tnfmerge, as alternates or supplements to this approach.

The TNF unbundled tools are components in a package that can be downloaded from the Solaris Developer Connection. TNFView is a tool that graphically displays TNF data. tnfmerge is a command line utility program that combines and sorts TNF data from one or more profiling executions. Hopefully, after reading this article, you will be able to use the TNF facilty in your performance tuning efforts.

TNF Overview

TNF is a system for generating and collecting execution event traces from the Solaris kernel and user processes. The output is a trace file that records TNF execution events. Either an application developer or a kernel process initiates a TNF software "probe" that records the event trace.

TNF APIs and programs enable a user to trace the execution of an application program or Solaris kernel activity. A TNF execution trace is a sequence of event records that are written to a file. An event record is written each time a probe--inserted into the application program or kernel source -- is executed. A probe marks a fixed location in a source program and it may designate, at the developer's option, values of target program scalar and string variables that are to be recorded as part of the resulting event record. Each record value is annotated with type information (such as int, long, char) and name information.

TNF execution traces mainly serve as a debugging aid during software development and for performance tuning. TNF is especially useful for debugging and tuning multi-threaded programs because a TNF probe automatically records thread-specific information (thread IDs, process IDs, etc.) in the event records written to a trace file.

The Solaris operating environment includes an API for inserting TNF probes into the source code of a C or C++ program. The API has commands to activate the probes in a subsequently compiled program. The formal API definition is TNF_PROBE(3TNF), while tracing(3TNF) provides an overview of the API and examples.

The TNF utility includes programs to make the task of trace analysis easier. One utility is tnfdump, located in /usr/bin/tnfdump. It displays trace file contents. The man page for this utility is tnfdump(1).

The Solaris operating environment kernel contains a number of TNF probes that are used to trace basic kernel events such as syscalls, I/O operations, pagein and pageout operations. An unbundled set of libraries and utilities extend these functions to extract TNF trace data from application programs without the need to modify and recompile source code.

Measurement

The basic performance metric provided by TNF records is the execution time as control flows between two points in a program. Unlike basic block oriented profiling, developers can place probes around application program operations composed of several blocks using TNF.

Performance Considerations

Inserting a probe for print or write statements can delay time interval measurements. For example, the execution time needed for print statement format conversions is substantial and can mask target program behaviors. All write and print statements can artificially limit concurrent execution in a multithreaded application program.

TNF records trace data in a binary format; conversion to developer-readable form is left to post-execution analysis. Furthermore, the TNF trace file is memory-mapped (threads are recorded to a file block that is not shared by another thread).

Maintainability

Performance tuning generally consists of traces from several different probe sites. The output from each of these probes must be distinctly labeled. Moreover, because the probes are inserted at different points in the source program, the trace data format from each probe will usually vary.

A program state recorded at one probe can differ in both name and type from a program state recorded at another probe. Synchronizing name and format information with subsequent analysis tools is a considerable effort, which is made even more difficult as changes are made to the target application.

TNF provides an extensive framework for naming trace data for recorded program state values, and for recording both name and type information. TNF incorporates this framework into a self-describing file format. The trace file also contains probe output names and record formats, which eliminates the need to maintain format information in a separate file.

Impact on Production Performance

TNF probes can be deployed in production versions of application programs. The performance of large and complex applications often depends on configuration parameters. These parameter values are usually determined when the application is installed and deployed. TNF data can be used to observe the effect of various settings and help in refining them to more optimal values. Thereafter, TNF tracing can be disabled with little residual impact on production performance. If only TNF interposition libraries are used, no residual impact on production performance will exist.

Instrumenting the Target - Overview

For performance tuning, TNF probes are used to measure the elapsed time between two points along the execution flow of the target program. A TNF probe is inserted at the endpoints of each measurement interval. When executed, the probe records identification information (naming strings and operating system assigned identifiers) and a time stamp value.

A TNF probe is a parameterized macro that allows a user to specify up to 5 argument values for the probe trace to record. These values can refer to variables in the target program address space. These values are evaluated during probe execution.

Example 1 shows a pair of probes that define an interval around a print statement. The trace output will contain records corresponding to these probes that are labeled printf_start and printf_end. These records will also include the values of the format_string and :value program variables.

Example 1

#include <tnf/probe.h> 
. 
.
TNF_PROBE_2(printf_start,  "printf i/o start", "example probe", 
tnf_opaque, printf_format, format_string, 
tnf_int, printf_operand, value)
printf(format_string, value);
TNF_PROBE_1(printf_end, "printf i/o end", "example probe", 
tnf_opaque, printf_format, format_string)

Inserting Probes

Inserting probes into C or C++ source is accomplished by inserting a probe macro invocation with the following format:

TNF_PROBE_n(name, keywords, detail, tnf_<arg type>, argname, argvalue,...).

• n is a digit between 0 and 5 that indicates the number of argument values to save.
• name is a unique identifier for the trace data record. If the probe is being used to define an interval, use the start/end or begin/end suffixes as a naming convention to automatically match the start/end or begin/end probes. Since probe names are not declared in the program address space, the developer needs to determine uniqueness.
• keywords and detail are strings used to group related probes for selective enabling and disabling of the target program execution.

In addition, since probe-defined intervals are generally executed many times, pairing a start record with the matching end record (for the same interval) requires the use of matching argument values.

Example 2 shows the address of the list_mutex variable being saved in each of the start/end probes. This allows start/end trace records with the same "save address" to be paired into the same interval.

Example 2

#include <tnf/probe.h> 
. 
.
extern mutex_t list_mutex; 
. 
.
TNF_PROBE_1(critical_start, 
   "critical section start", 
   "mutex acquire", 
   tnf_opaque, list_lock, 
&list_mutex)
mutex_lock(&list_mutex); 
. 
.
/* critical section code */ 
. 
.
mutex_unlock(&list_mutex)
TNF_PROBE_1(critical_end, 
"critical section end", 
"mutex release", 
tnf_opaque, list_lock, &list_mutex)

Compiling and linking probe-instrumented source files requires no special compiler or linker switches. Compilation of inserted probes can be suppressed by defining the pre-processor macro NPROBE. Documentation for the NPROBE macro is included in the TNF_PROBE(3TNF) man page.

Interposition Libraries

The unbundled TNF tools include interposition libraries that allow a target program to be instrumented when the target program source cannot be either altered and recompiled, or the source is unavailable.

Interposition libraries redirect calls from selected functions to wrapper functions in the Solaris thread libraries, libthread, libpthread, and libc, that effectively enclose a function call between a pair of TNF probes. Call redirection works only with calls to dynamically linked entry points in share libraries (objects).

Example 3 shows how the interposition mechanism works.

Example 3

#include <tnf/probe.h> 
. 

Void interposed(unsigned v) { 
typedef void (*)(unsigned) T; 
T *target; 
target = (T *)dlopen(.., "interposed"); 
TNF_PROBE_1(interposed_start 
"interposed start", 
"interposed", 
tnf_uint, v, v) 
target(v); 
TNF_PROBE_0("interposed_end", 
"interposed end", 
"interposed")
}

Collecting Data

By default, tracing is disabled at each probe in an instrumented program. The prex command must be used to enable tracing at a probe. The prex command can also be used to load the target program into memory and enable tracing before the program begins execution. Alternately, prex can:

• Suspend program execution
• Enable tracing
• Disable tracing
• Resume program execution

Example 4 shows how an instrumented program is loaded, tracing is enabled, and output is directed to a trace file in the current working directory. Once the program is resumed, it will execute until complete.

Example 4

prex -o tracefile target_program
prex>enable $all
prex>continue

Example 5 shows the use of the libthread_probe. This probe enables the interposition library to trace libpthread calls made by the target program. When the -o option is not present, trace output is written to /tmp/trace-<target process id>.

Example 5

UNBUNDLED=/net/suntools/export/tools/`uname -p`/lib
prex -l $UNBUNDLED/libpthread_probe.so target
prex>enable $all
prex>continue

Example 6 shows how the prex command is used, after the target program is started with tracing disabled, to suspend execution, enable tracing, and resume execution. The LD_PRELOAD environment variable is used to load the TNF functions that perform the output tracing. When using LD_PRELOAD, this must be done explicitly. (This is implicitly done when the target is loaded by prex.)

Example 6

env LD_PRELOAD="/usr/lib/libtnfprobe.so" target &
prex -p `pgrep target`
Target process stopped
Type "continue" to resume the target, "help" for help ...
prex>enable $all
prex>continue

Example 7 is the same as Example 6, but uses an interposition library. When LD_PRELOAD is needed to load both the tracing support library and the interposition library, the libtnfprobe library must appear before all other libraries.

Example 7

UNBUNDLED=/net/suntools/export/tools/`uname -
p`/lib/libpthread_probe.so
env  LD_PRELOAD="/usr/lib/libtnfprobe.so $UNBUNDLED" target &
Target process stopped
Type "continue" to resume the target, "help" for help ...
prex>enable $all
prex>continue

As Examples 6 and 7 show, it is possible to enable tracing in a program that is already running. In addition, it is possible for the user ID under the executing program to differ from the user ID under which prex is run and used to create the trace file. In this situation, the trace file must be located (using -o) in a directory where both user IDs have write access to the file. In particular, locating files in /tmp will result in file access problems that will suppress tracing output.

Example 8 shows how the existing Solaris probes, as well as probes in the currently loaded kernel modules, are enabled. Only the root user ID can execute the commands shown. Kernel trace data is recorded in a contiguous portion of the kernel virtual address space and cannot be directly viewed.

The tnfxtract command is used to extract the current contents of the kernel trace buffer into a separate file where the content can be directly viewed. The tnfxtract command can be run any number of times and has no effect on the state (enabled or disabled) of kernel tracing.

Example 8

prex -k
prex>ktrace on
prex>buffer alloc
prex>enable $all
prex>continue 

tnfxtract tracefile

Analyzing the Data

Analyzing trace data involves forming interval pairs from the collected trace data.

Event trace data must be sorted by the timestamp value. The tnfmerge utility from the unbundled tools can be used to perform this step. Unlike sorted tnfdump output, tnfmerge produces a sorted trace that is readable by the unbundled visual analysis tool TNFView.

TNFView partitions the sorted trace data into intervals, and by use of scatter plots and histograms, visually highlights clusters and outliers to indicate possible performance bottlenecks. This partitioning is based on probe name pairs specified by the user and pair events that use matching argument name/argument value pairs.

In addition to the scatter plots and histograms, TNFView produces a global timeline of the trace file. Clicking on interval points on the scatter plot causes the time line view to highlight events. Individual field values appear in the event trace record and are listed in a table that appears under the time line display area.

Figure 1: TNFView Scatterplot (Click image to enlarge)

Figure 2: TNFView Timeline (Click image to enlarge)

The tnfmerge utility can be used to combine several trace files into a single trace file. Results from several program executions can be accumulated into one file, or results from concurrent executions from a set of inter-related programs can be merged into a single view.

Obtaining Bundled and Unbundled TNF Components

The probe insertion API is bundled with Solaris and is available in the TNF developer package, SUNWtnfd. Interposition libraries and tools, such as tnfmerge and TNFView, are unbundled and available as downloads from the Solaris Developer Connection.

The components for inserting probes into a source program and generating a trace file are part of the SUNWtnfc package for 32-bit systems, and the SUNWtnfcx package for 64-bit systems. The tnfdump and components needed to run TNFView are part of the SUNWtnfd package.

A quick test for the presence of these packages is:

pkginfo | grep tnf

If the packages are present, the following output will appear:

system      SUNWtnfc       TNF Core Components
system      SUNWtnfcx      TNF Core Components (64-bit)
system      SUNWtnfd       TNF Developer Components

These packages are automatically installed if you request the SUNWCprog software cluster when Solaris is first installed or upgraded. These packages can also be subsequently added by running /usr/bin/admintool as the root user. To perform this addition:

1. Browse "software."
2. Select TNF Core Components, in the "System Software" category.
3. Install TNF Core Components and TNF Developer Components.

The man pages for TNF components and APIs include:

• tracing(3TNF) - Provides a brief overview, with examples, of the capabilities provided by TNF.
• tnf_kernel_probes(4) - Describes the TNF probes in the kernel and resident, unloadable modules. Documentation of TNF probes in a loadable module such as a device driver, if available, is provided in the documentation for that module.
• TNF_PROBE - Describes the various probes available for insertion into source programs. Any compilation options needed are also described.

The unbundled TNF components and APIs that extend the basic capabilities include:

• tnfview - A Motif-based TNF trace viewer that provides a visual time-ordered and thread-ordered display of the event traces in a TNF trace file.
• tnfmerge - A merge utility that combines one or more tracefiles into a single tracefile, ordered by trace event timestamp. (tnfview requires tracefiles of this type.) These tracefiles are also readable by tnfdump.
• tnftrace - A wrapper script that invokes a target application, enables TNF tracing, and executes the application with the correct environment settings.

Register and download the tools.

About the Author

John Murayamo is the project leader on the TNF project. He is a staff engineer in the Software Tools and Technology group in the Solaris sustaining organization; for the past four years he has worked primarily on the TNF project. Before joining Sun, John gained extensive experience working on compiler front-end and back-end components.

July, 2001

Back to Top