Solutions for tracing UNIX applications

Page 4 of 10  Document options PDF - Fits A4 and Letter 66 KB (24 pages) Get Adobe® Reader® Sample code My developerWorks needs you! Connect to your technical community Rate this tutorial Help us improve this content

Dynamic tracing with DTrace

The Dynamic Tracing (DTrace) functionality built into Solaris, FreeBSD, and Mac OS X provides, as the name suggests, a more dynamic tracing environment. Unlike truss and similar tools, DTrace enables you to examine the internals of the programs you are running, and not just the system calls. Furthermore, with DTrace you can script the tracing of an application to customize the information you want to extract during the tracing process.

DTrace overview

DTrace combines many of the principles of the tracing that you have already seen with truss and strace, but adds a great deal of flexibility to the method and mechanism used to trace an application.

Unlike truss and strace, which list only functions within the kernel space, DTrace can be used to show the function names of the application, any libraries on which it relies, and the functions in the kernel that are called. This extends the usability of the tracing almost to the same level as a debugger. However, unlike a debugger, you cannot modify the values, and you cannot pause or otherwise alter the execution of the application. You are limited to tracing the execution, not controlling it.

The other key element of DTrace compared to both tracing and the majority of debuggers is that you can write a script that defines what to trace within the application, and information should be reported when the application executes. For example, you can specify that DTrace report only on a specific function, and that it prints out a single argument from the function call.

In addition to printing specific information, DTrace also provides built-in support for a number of utility values and functions. Within a script, for example, you can record a timestamp of when the function was called, and then compare the timestamp value with the timestamp when the function completes. By comparing the two values you can obtain the execution time for a specific function, or operation, and use the tracing information to provide execution and performance statistics.

Probes and providers

DTrace works by adding instrumentation to the system that identifies different points of execution. These points are called probes and include probes defined within the kernel, libraries, and programs. All functions within the kernel, libraries, and user programs can be identified as a probe. In addition, statically defined probes can be used to identify special points of interest. For example, the kernel includes probes that can be used to identify when data is written to a disk. As a developer, you can add specific probes to your program to enable tracing by your users. These probes are identified as User-land Statically Defined Tracing, or USDT.

Probes are identified using the following structure: provider:module:function:name, where provider is the name of the provider (for example, the name of a program, or a specific part of the kernel or operating system). The module is the kernel module or library, and the function is usually the function name within the module or program, and the name identifies the probe. The provider also has a special identifier, the PID provider, which is used to identify any running program and can be used to trace any function within a running program.

The name is usually the name of a specific probe within the system or program that has been specifically defined. DTrace also supports function boundary tracing (FBT), which enables you to trace the entry and return from any function within the kernel, library or an application. With FBT, the entry probe is triggered when the function is called, and the return probe is triggered when the function returns or completes.

Any of the components within the probe specification can either be omitted (in which case the probe specification matches all items) or with a wildcard. For example, you can specify all of the probes within a given provider using: provider:::. Or you can specify only the entry probes on a PID provider: pid$target:::entry.

The above probe specification is similar to the operation of truss, except that the functions will cover both the program, the operating system, and any libraries on which the program relies. This provides a much wider scope than truss.

When using the PID provider, the module can be used to identify the program. Without this specification, you trace every function called by the program. By specifying the program name, you limit the output to the functions defined within the program. For example, to trace the execution of the functions within the ageindays command, you might use: pid$target:ageindays::.

Any program can be traced using dtrace; you do not compile the program in a specific way. This means that unlike truss, you can gain a deeper understanding of an application even if you don't own the source to the program in question.

You can obtain a list of probes using the dtrace tool; the -l command line option will list all of the probes defined in the system: $ dtrace -l.

The list can be many thousands of lines long.

Back to top

One-line tracing

As already noted, you can trace any application and any function within that application using DTrace. There are three ways to use dtrace from the command line: specifying a command; specifying a process ID; or specifying a named, static, probe.

Specify a command on the command-line to be executed (using -c), and specify the probe you want to monitor using the -n option (see Listing 10).

$ dtrace -n 'pid$target:ageindays::entry' -c './ageindays 24/1/1980 26/3/1980'
dtrace: description 'pid$target:ageindays::entry' matched 7 probes
You have been alive 62 days
You were born on 24/1/1980 which is a Thursday
dtrace: pid 15925 has exited
CPU     ID                    FUNCTION:NAME
  1  57147                     _start:entry 
  1  57148                      __fsr:entry 
  1  57153                       main:entry 
  1  57152                  check_day:entry 
  1  57152                  check_day:entry 
  1  57151                  calc_diff:entry 
  1  57150                  leap_year:entry 
...

Now specify the process ID of a program already running, and the probe that you want to trace. For example, the line in Listing 11 traces calls to the syslog system by the inetd daemon.

$ dtrace -n 'pid$target::syslog:entry { printf("%d %s", arg0, copyinstr(arg1)) }' 
   -p `pgrep -x inetd`

Or you can specify the name of a static probe, which will match all of the probes within any running process. For example, the line in Listing 12 looks for any exec functions being called (for example, when a user runs a command in a shell). Because you haven't specified a specific process, this probe will work for any call to the function by any user on the system (see Listing 12).

$ dtrace -n 'syscall::exec*:entry'
dtrace: description 'syscall::exec*:entry' matched 2 probes
CPU     ID                    FUNCTION:NAME
  0  56750                      exece:entry 
  0  56750                      exece:entry 
  0  56750                      exece:entry 

In all of these examples, you have only used the basic output, which just outputs the function or probe name, and the CPU and process ID where the probe was triggered. More extensive and selective probing and custom output is available by using the D scripting language.

Back to top

Writing a DTrace script

The DTrace scripting language provides a simple mechanism for executing specific operations (called actions) when a probe is triggered by a provider. The language is limited in that you do not have the flexibility of a full language environment such as PHP or Perl, but you do have the ability to record information into variables, perform basic calculations, and support basic decision making.

A basic example that prints out the values when a specific probe is executed is shown below. The arguments to a probe or function are available using the aliases arg0, arg1, and so on for each argument. For this example, you are monitoring all of the functions starting with those open for a given process, and printing out the file opened in each case.

#!/bin/dtrace -s

#pragma D option quiet

pid$target::open*:entry
{
   printf("Opened: %s\n",copyinstr(arg0));
}

You can save this text into a file called open.t, and then set the execute bit on the file: $ chmod +x open.t.

The file is now an executable script. To use it, supply the process ID with the -p command line option. For example, running it against a shell, you get the list of files the shell opens during execution (see Listing 14).

$ ./open.t -p 15930
Opened: /root/.bash_path
Opened: /root/.bash_vars
Opened: /root/.bashrc
Opened: /root/.bash_aliases
...

A more typical use for DTrace scripts is to aggregate and summarize information, and provide counters and time differences between different operations. The probes within a DTrace script are executed sequentially within a single thread, which means that you can monitor the execution of a series of probes. Many probes are provided in pairs, with the start probe indicating where an operation begins, and the done probe where an operation completes.

By recording the time when the start probe was triggered, and then when the probe completed, you can determine how long the operation took to complete. Within a DTrace script, the self variable can be used to hold the start time. For example, the script in Listing 15 uses named probes within the MySQL database system to monitor the execution time of a query.

#!/usr/sbin/dtrace -s

#pragma D option quiet

dtrace:::BEGIN
{
   printf("%-80s %6s\n", "Query", "Duration (ms)");
}

mysql*:::query-start
{
   self->query = copyinstr(arg5);
   self->querystart = timestamp;
}

mysql*:::query-done
{
   this->elapsed = (timestamp - self->querystart) /1000000;
   printf("%-80s %6d\n", self->query, this->elapsed);
}

The trace shows a number of different elements of a typical DTrace script. First, the BEGIN block outputs some header information, which is useful when you are printihg out tabulated data.

The query-start probes include a number of arguments, and the sixth argument (arg5) contains the full text of the original query.

When running the query on a server running MySQL, you can get useful statistics about the time taken to run each query (see Listing 16).

$ ./basic.d
Query                                                           Duration (ms)
show tables                                                     203
select * from t1 where i <5                                  131526

These examples have barely scratched the surface of what DTrace is capable of achieving. See Resources for more examples and information.

Back to top

	Page 4 of 10