Output Formatting

System call tracing is a powerful way to observe the behavior of most user processes. If you've used the Solaris truss(1) utility before as an administrator or developer, you've probably learned that it's a useful tool to keep around for whenever there is a problem. If you've never used truss before, give it a try right now by typing this command into one of your shells:

$ truss date

You will see a formatted trace of all the system calls executed by date(1) followed by its one line of output at the end. The following example improves upon the earlier rw.d program by formatting its output to look more like truss(1) so you can more easily understand the output. Type the following program and save it in a file called trussrw.d:

Example 1-2 trussrw.d: Trace System Calls with truss(1) Output Format

syscall::read:entry,
syscall::write:entry
/pid == $1/
{
    printf("%s(%d, 0x%x, %4d)", probefunc, arg0, arg1, arg2);
}

syscall::read:return,
syscall::write:return
/pid == $1/
{
    printf("\t\t = %d\n", arg1);
}

In this example, the constant 12345 is replaced with the label $1 in each predicate. This label allows you to specify the process of interest as an argument to the script: $1 is replaced by the value of the first argument when the script is compiled. To execute trussrw.d, use the dtrace options -q and -s, followed by the process ID of your shell as the final argument. The -q option indicates that dtrace should be quiet and suppress the header line and the CPU and ID columns shown in the preceding examples. As a result, you will only see the output for the data that you explicitly traced. Type the following command (replacing 12345 with the process ID of a shell process) and then press return a few times in the specified shell:

# dtrace -q -s trussrw.d 12345
                     = 1
write(2, 0x8089e48,    1)                = 1
read(63, 0x8090a38, 1024)                = 0
read(63, 0x8090a38, 1024)                = 0
write(2, 0x8089e48,   52)                = 52
read(0, 0x8089878,    1)                 = 1
write(2, 0x8089e48,    1)                = 1
read(63, 0x8090a38, 1024)                = 0
read(63, 0x8090a38, 1024)                = 0
write(2, 0x8089e48,   52)                = 52
read(0, 0x8089878,    1)                 = 1
write(2, 0x8089e48,    1)                = 1
read(63, 0x8090a38, 1024)                = 0
read(63, 0x8090a38, 1024)                = 0
write(2, 0x8089e48,   52)                = 52
read(0, 0x8089878,    1)^C
#

Now let's examine your D program and its output in more detail. First, a clause similar to the earlier program instruments each of the shell's calls to read(2) and write(2). But for this example, a new function, printf(), is used to trace data and print it out in a specific format:

syscall::read:entry,
syscall::write:entry
/pid == $1/
{
    printf("%s(%d, 0x%x, %4d)", probefunc, arg0, arg1, arg2);
}

The printf() function combines the ability to trace data, as if by the trace() function used earlier, with the ability to output the data and other text in a specific format that you describe. The printf() function tells DTrace to trace the data associated with each argument after the first argument, and then to format the results using the rules described by the first printf() argument, known as a format string.

The format string is a regular string that contains any number of format conversions, each beginning with the % character, that describe how to format the corresponding argument. The first conversion in the format string corresponds to the second printf() argument, the second conversion to the third argument, and so on. All of the text between conversions is printed verbatim. The character following the % conversion character describes the format to use for the corresponding argument. Here are the meanings of the three format conversions used in trussrw.d:

%d	Print the corresponding value as a decimal integer
%s	Print the corresponding value as a string
%x	Print the corresponding value as a hexadecimal integer

DTrace printf() works just like the C printf(3C) library routine or the shell printf(1) utility. If you've never seen printf() before, the formats and options are explained in detail in Chapter 12, Output Formatting. You should read this chapter carefully even if you're already familiar with printf() from another language. In D, printf() is provided as a built-in and some new format conversions are available to you designed specifically for DTrace.

To help you write correct programs, the D compiler validates each printf() format string against its argument list. Try changing probefunc in the clause above to the integer 123. If you run the modified program, you will see an error message telling you that the string format conversion %s is not appropriate for use with an integer argument:

# dtrace -q -s trussrw.d
dtrace: failed to compile script trussrw.d: line 4: printf( )
       argument #2 is incompatible with conversion #1 prototype:
            conversion: %s
             prototype: char [] or string (or use stringof)
              argument: int
#

To print the name of the read or write system call and its arguments, use the printf() statement:

printf("%s(%d, 0x%x, %4d)", probefunc, arg0, arg1, arg2);

to trace the name of the current probe function and the first three integer arguments to the system call, available in the DTrace variables arg0, arg1, and arg2. For more information about probe arguments, see Chapter 3, Variables. The first argument to read(2) and write(2) is a file descriptor, printed in decimal. The second argument is a buffer address, formatted as a hexadecimal value. The final argument is the buffer size, formatted as a decimal value. The format specifier %4d is used for the third argument to indicate that the value should be printed using the %d format conversion with a minimum field width of 4 characters. If the integer is less than 4 characters wide, printf() will insert extra blanks to align the output.

To print the result of the system call and complete each line of output, use the following clause:

syscall::read:return,
syscall::write:return
/pid == $1/
{
    printf("\t\t = %d\n", arg1);
}

Notice that the syscall provider also publishes a probe named return for each system call in addition to entry. The DTrace variable arg1 for the syscall return probes evaluates to the system call's return value. The return value is formatted as a decimal integer. The character sequences beginning with backwards slashes in the format string expand to tab (\t) and newline (\n) respectively. These escape sequences help you print or record characters that are difficult to type. D supports the same set of escape sequences as C, C++, and the Java programming language. The complete list of escape sequences is found in Chapter 2, Types, Operators, and Expressions.