DTrace's interaction with processes is slightly different than most traditional debuggers and observability tools. Many such tools appear to execute within the scope of the process, allowing users dereference pointers to program variables directly. Rather than appearing to execute within or as part of the process itself, DTrace probes execute in the Oracle Linux kernel. To access process data, a probe uses the copyin or copyinstr subroutines to copy user process data into the address space of the kernel.

For example, consider the following write() system call:

ssize_t write(int fd, const void *buf, size_t nbytes);

The following D program illustrates an incorrect attempt to print the contents of a string that is passed to the write() system call:

syscall::write:entry
{
  printf("%s", stringof(arg1)); /* incorrect use of arg1 */
}

If you attempt to run this script, DTrace produces error messages similar to the following:

dtrace: error on enabled probe ID 1 (ID 37: syscall::write:entry): \
invalid address (0x10038a000) in action #1

The arg1 variable, which contains the value of the buf parameter, is an address that refers to memory in the process executing the system call. To read the string at that address, use the copyinstr subroutine and record its result with the printf action, for example:

syscall::write:entry
{
  printf("%s", copyinstr(arg1)); /* correct use of arg1 */
}

In the previous script, the output shows all of the strings that are being passed to the write() system call. Occasionally, however, you might see irregular output similar to the following:

 0         37                     write:entry mada&^%**&

The copyinstr subroutine acts on an input argument, which is the user address of a null-terminated ASCII string, but buffers that are passed to the write() system call might refer to binary data rather than ASCII strings or to ASCII strings that do not include a terminating null byte. To print only as much of the string as the caller intended, use the two parameter version of the copyinstr subroutine, which includes the size of the targeted string buffer:

syscall::write:entry { printf("%s", copyinstr(arg1, arg2)); }

Alternatively, you can use the copyin subroutine, which takes an address and size, for example:

syscall::write:entry
{
  printf("%s", stringof(copyin(arg1, arg2)));
}

Note that the stringof operator is necessary so that DTrace properly converts the user data that is retrieved by copyin to a string. The use of stringof is not necessary with the copyinstr subroutine because it always returns the type string.

If you trace every call to the write() system call, it causes a cascade of output because each call causes the dtrace command to call write() as it displays the output, and so on. This feedback loop is a good example of how the dtrace command can interfere with the desired data. To prevent this type of unwanted data from being traced, use a simple predicate like the one that is shown in the following example and save it in a file named stringof.d:

syscall::write:entry
/pid != $pid/
{
  printf("%s", stringof(copyin(arg1, arg2)));
}

In the previous example, the $pid macro variable expands to the process identifier of the process that enabled the probes. The pid variable contains the process identifier of the process whose thread was running on the CPU where the probe was fired. Therefore, the predicate /pid != $pid/ ensures that the script does not trace any events related to itself.

The syscall provider enables you to trace every system call entry and return. System calls can be a good starting point for understanding the behavior of a process, especially if the process seems to be spending a large amount of time executing or blocked in the kernel, as shown in the output of commands such as ps and top.

For example, consider a process with a process ID of 31337 that is consuming a large amount of system time. One possible explanation for this behavior is that the process is executing a large number of system calls. You can specify a simple D program on the command line to see which system calls are happening most often:

# dtrace -n syscall:::entry'/pid == 31337/{ @syscalls[probefunc] = count(); }'
dtrace: description ’syscall:::entry’ matched 215 probes
^C

  kill                                                              1
  clone                                                             4
  pipe                                                              4
  setpgid                                                           4
  rt_sigreturn                                                      6
  sendmsg                                                           7
  socket                                                            7
  access                                                            8
  getegid                                                           8
  geteuid                                                           8
  getgid                                                            8
  getuid                                                            8
  wait4                                                            12
  close                                                            15
  read                                                             23
  newstat                                                          25
  write                                                            42
  ioctl                                                            65
  rt_sigaction                                                    168
  rt_sigprocmask                                                  198
  write                                                          1092

The previous report shows the system calls that are being called most often, which in this case, is the write() system call.

You can use the syscall provider to further examine the source of all of the write() system calls, for example:

# dtrace -n syscall::write:entry'/pid == 31337/{ @writes = quantize(arg2); }'
dtrace: description ’syscall::write:entry’ matched 1 probe
^C

          value  ------------- Distribution ------------- count
              0 |                                         0
              1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   1037
              2 |@                                        3
              4 |                                         0
              8 |                                         0
             16 |                                         0
             32 |@                                        3
             64 |                                         0
            128 |                                         0
            256 |                                         0
            512 |                                         0
           1024 |@                                        5

The previous output shows that the process is executing many write() system calls with a relatively small amount of data. The ratio could be the source of the performance problem for this particular process. This example illustrates a general methodology for investigating system call behavior.

Tracing a process thread's stack when a particular probe is activated is often useful for examining a problem in more detail. The ustack action traces the user thread's stack. For example, if a process that opens many files occasionally fails in the open() system call, you can use the ustack action to discover the code path that executes the failed open. Type the following source code and save it in a file named badopen.d:

syscall::open:entry
/pid == $1/
{
  self->path = copyinstr(arg0);
}

syscall::open:return
/self->path != NULL && errno != 0/
{
  printf("open for '%s' failed", self->path);
  ustack();
}

This script also illustrates the use of the $1 macro variable, which takes the value of the first operand that is specified on the dtrace command line:

# dtrace -s ./badopen.d 3430
dtrace: script './badopen.d' matched 2 probes
CPU     ID                    FUNCTION:NAME
  1    489                    openat:return open for '/usr/lib/foo' failed
              libc.so.6`sleep+0xe0
              ld-linux-x86-64.so.2`do_lookup_x+0x847
              libc.so.6`0x3cb8003630
              libc.so.6`0x3cb8003c48
              libc.so.6`0x3cb800e2c8
              libc.so.6`0x3cb8003c48
              looper`0x400612
              libc.so.6`getenv+0x2a
              looper`0x4003c8
              looper`0x4009b0
              libc.so.6`0x3cb800e2c8
              looper`0x4009b0
              looper`doOpenLoop+0x33
              looper`0x400e9c
              looper`main+0x5f
              looper`0x400ea9
              libc.so.6`__libc_start_main+0xfd
              looper`main
              looper`0x4009b0
              looper`__libc_csu_init

The ustack action records program counter (PC) values for the stack and the dtrace command resolves the PC values to symbol names by looking though the process's symbol tables. If dtrace cannot resolve the PC value to a symbol, it prints out the value as a hexadecimal integer.

If a process exits or is killed before the ustack data is formatted for output, dtrace might be unable to convert the PC values in the stack trace to symbol names and the command displays them as hexadecimal integers.

The uregs[] array enables you to access individual user registers. See Table 12-1, which lists the index constants into the uregs[] array for each supported architecture.

The following table lists the index constants into the uregs[] array for each supported architecture.

The pid provider enables you to trace any instruction in a process. Unlike most other providers, pid probes are created on demand, based on the probe descriptions that are found in your D programs. As a result, no pid probes are listed in the output of the dtrace -l command until you enable them.