Dynamic Tracing Guide
PreviousNext
Chapter 37

Postmortem Tracing

This chapter describes the DTrace facilities for postmortem extraction and processing of the in-kernel data of DTrace consumers. In the event of a system crash, the information that has been recorded with DTrace may provide the crucial clues to root-cause the system failure. DTrace data may be extracted and processed from the system crash dump to aid you in understanding fatal system failures. By coupling these postmortem capabilities of DTrace with its ring buffering buffer policy (see Chapter 11, Buffers and Buffering), DTrace can be used as an operating system analog to the black box flight data recorder present on commercial aircraft.

To extract DTrace data from a specific crash dump, you should begin by running the illumos Modular Debugger, mdb(1), on the crash dump of interest. The MDB module containing the DTrace functionality will be loaded automatically. To learn more about MDB, refer to the illumos Modular Debugger Guide.

Displaying DTrace Consumers

To extract DTrace data from a DTrace consumer, you must first determine the DTrace consumer of interest by running the ::dtrace_state MDB dcmd:

> ::dtrace_state
    ADDR MINOR     PROC NAME                 FILE
ccaba400     2        - <anonymous>             -
ccab9d80     3 d1d6d7e0 intrstat         cda37078
cbfb56c0     4 d71377f0 dtrace           ceb51bd0
ccabb100     5 d713b0c0 lockstat         ceb51b60
d7ac97c0     6 d713b7e8 dtrace           ceb51ab8

This command displays a table of DTrace state structures. Each row of the table consists of the following information:

  • The address of the state structure

  • The minor number associated with the dtrace(7D) device

  • The address of the process structure that corresponds to the DTrace consumer

  • The name of the DTrace consumer (or <anonymous> for anonymous consumers)

  • The name of the file structure that corresponds to the open dtrace(7D) device

To obtain further information about a specific DTrace consumer, specify the address of its process structure to the ::ps dcmd:

> d71377f0::ps
S    PID   PPID   PGID    SID    UID      FLAGS     ADDR NAME
R 100647 100642 100647 100638      0 0x00004008 d71377f0 dtrace

Displaying Trace Data

Once you determine the consumer of interest, you can retrieve the data corresponding to any unconsumed buffers by specifying the address of the state structure to the ::dtrace dcmd. The following example shows the output of the ::dtrace dcmd on an anonymous enabling of syscall:::entry with the action trace(execname):

> ::dtrace_state
    ADDR MINOR     PROC NAME                 FILE
cbfb7a40     2        - <anonymous>             -

> cbfb7a40::dtrace
CPU     ID                    FUNCTION:NAME
  0    344                resolvepath:entry   init                           
  0     16                      close:entry   init                           
  0    202                      xstat:entry   init                           
  0    202                      xstat:entry   init                           
  0     14                       open:entry   init                           
  0    206                     fxstat:entry   init                           
  0    186                       mmap:entry   init                           
  0    186                       mmap:entry   init                           
  0    186                       mmap:entry   init                           
  0    190                     munmap:entry   init                           
  0    344                resolvepath:entry   init                           
  0    216                    memcntl:entry   init                           
  0     16                      close:entry   init                           
  0    202                      xstat:entry   init                           
  0     14                       open:entry   init                           
  0    206                     fxstat:entry   init                           
  0    186                       mmap:entry   init                           
  0    186                       mmap:entry   init                           
  0    186                       mmap:entry   init                           
  0    190                     munmap:entry   init
...

The ::dtrace dcmd handles errors in the same way that dtrace(1M) does: if drops, errors, speculative drops, or the like were encountered while the consumer was executing, ::dtrace will emit a message corresponding to the dtrace(1M)message.

The order of events as displayed by ::dtrace is always oldest to youngest within a given CPU. The CPU buffers themselves are displayed in numerical order. If an ordering is required for events on different CPUs, trace the timestamp variable.

You can display only the data for a specific CPU by specifying the -c option to ::dtrace:

> cbfb7a40::dtrace -c 1
CPU     ID                    FUNCTION:NAME
  1     14                       open:entry   init
  1    206                     fxstat:entry   init
  1    186                       mmap:entry   init
  1    344                resolvepath:entry   init
  1     16                      close:entry   init
  1    202                      xstat:entry   init
  1    202                      xstat:entry   init
  1     14                       open:entry   init
  1    206                     fxstat:entry   init 
  1    186                       mmap:entry   init  
...

Notice that ::dtrace only processes in-kernel DTrace data. Data that has been consumed from the kernel and processed (through dtrace(1M) or other means) will not be available to be processed with ::dtrace. To assure that the most amount of data possible is available at the time of failure, use a ring buffer buffering policy. See Chapter 11, Buffers and Buffering for more information on buffer policies.

The following example creates a very small (16K) ring buffer and records all system calls and the process making them:

# dtrace -P syscall'{trace(curpsinfo->pr_psargs)}' -b 16k -x bufpolicy=ring
dtrace: description 'syscall:::entry' matched 214 probes

Looking at a crash dump taken when the above command was running results in output similar to the following example:

> ::dtrace_state
    ADDR MINOR     PROC NAME                 FILE
cdccd400     3 d15e80a0 dtrace           ced065f0

> cdccd400::dtrace
CPU     ID                    FUNCTION:NAME
  0    139                    getmsg:return   mibiisa -r -p 25216            
  0    138                     getmsg:entry   mibiisa -r -p 25216            
  0    139                    getmsg:return   mibiisa -r -p 25216            
  0    138                     getmsg:entry   mibiisa -r -p 25216            
  0    139                    getmsg:return   mibiisa -r -p 25216            
  0    138                     getmsg:entry   mibiisa -r -p 25216            
  0    139                    getmsg:return   mibiisa -r -p 25216            
  0    138                     getmsg:entry   mibiisa -r -p 25216            
  0    139                    getmsg:return   mibiisa -r -p 25216            
  0    138                     getmsg:entry   mibiisa -r -p 25216            
  0     17                     close:return   mibiisa -r -p 25216            
...
  0     96                      ioctl:entry   mibiisa -r -p 25216            
  0     97                     ioctl:return   mibiisa -r -p 25216            
  0     96                      ioctl:entry   mibiisa -r -p 25216            
  0     97                     ioctl:return   mibiisa -r -p 25216            
  0     96                      ioctl:entry   mibiisa -r -p 25216            
  0     97                     ioctl:return   mibiisa -r -p 25216            
  0     96                      ioctl:entry   mibiisa -r -p 25216            
  0     97                     ioctl:return   mibiisa -r -p 25216            
  0     16                      close:entry   mibiisa -r -p 25216            
  0     17                     close:return   mibiisa -r -p 25216            
  0    124                   lwp_park:entry   mibiisa -r -p 25216            
  1     68                     access:entry   mdb -kw                        
  1     69                    access:return   mdb -kw                        
  1    202                      xstat:entry   mdb -kw                        
  1    203                     xstat:return   mdb -kw                        
  1     14                       open:entry   mdb -kw                        
  1     15                      open:return   mdb -kw                        
  1    206                     fxstat:entry   mdb -kw                        
  1    207                    fxstat:return   mdb -kw                        
  1    186                       mmap:entry   mdb -kw                        
...
  1     13                     write:return   mdb -kw                        
  1     10                       read:entry   mdb -kw                        
  1     11                      read:return   mdb -kw                        
  1     12                      write:entry   mdb -kw                        
  1     13                     write:return   mdb -kw                        
  1     96                      ioctl:entry   mdb -kw                        
  1     97                     ioctl:return   mdb -kw                        
  1    364                    pread64:entry   mdb -kw                        
  1    365                   pread64:return   mdb -kw                        
  1    366                   pwrite64:entry   mdb -kw                        
  1    367                  pwrite64:return   mdb -kw                        
  1    364                    pread64:entry   mdb -kw                        
  1    365                   pread64:return   mdb -kw                        
  1     38                        brk:entry   mdb -kw                        
  1     39                       brk:return   mdb -kw                        
>

Note that CPU 1's youngest records include a series of write(2) system calls by an mdb -kw process. This result is likely related to the reason for the system failure because a user can modify running kernel data or text with mdb(1) when run with the -k and -w options. In this case, the DTrace data provides at least an interesting avenue of investigation, if not the root cause of the failure.

PreviousNext