25.4 Using DTrace

Before making use of DTrace functionality, the DTrace device must exist. To load the device, issue the following command:

# kldload dtraceall

DTrace support should now be available. To view all probes the administrator may now execute the following command:

# dtrace -l | more

All output is passed to the more utility as it will quickly overflow the screen buffer. At this point, DTrace should be considered working. It is now time to review the toolkit.

The toolkit is a collection of ready-made scripts to run with DTrace to collect system information. There are scripts to check open files, memory, CPU usage and a lot more. Extract the scripts with the following command:

# gunzip -c DTraceToolkit* | tar xvf -

Change into that directory with the cd and change the execution permissions on all files, designated as those files with lower case names, to 755.

All of these scripts will need modifications to their contents. The ones which refer to /usr/bin/ksh need that changed to /usr/local/bin/ksh, the others which use /usr/bin/sh need to be altered to use /bin/sh, and finally the ones which use /usr/bin/perl will need altered to use /usr/local/bin/perl.

At the time of this writing only two of the scripts of the DTrace Toolkit are fully supported in FreeBSD: the hotkernel and procsystime scripts. These are the two we will explore in the following parts of this section.

The hotkernel is designed to identify which function is using the most kernel time. Run normally, it will produce output similar to the following:

# ./hotkernel
Sampling... Hit Ctrl-C to end.

The system administrator must use the Ctrl+C key combination to stop the process. Upon termination, the script will display a list of kernel functions and timing information, sorting the output in increasing order of time:

kernel`_thread_lock_flags                                   2   0.0%
0xc1097063                                                  2   0.0%
kernel`sched_userret                                        2   0.0%
kernel`kern_select                                          2   0.0%
kernel`generic_copyin                                       3   0.0%
kernel`_mtx_assert                                          3   0.0%
kernel`vm_fault                                             3   0.0%
kernel`sopoll_generic                                       3   0.0%
kernel`fixup_filename                                       4   0.0%
kernel`_isitmyx                                             4   0.0%
kernel`find_instance                                        4   0.0%
kernel`_mtx_unlock_flags                                    5   0.0%
kernel`syscall                                              5   0.0%
kernel`DELAY                                                5   0.0%
0xc108a253                                                  6   0.0%
kernel`witness_lock                                         7   0.0%
kernel`read_aux_data_no_wait                                7   0.0%
kernel`Xint0x80_syscall                                     7   0.0%
kernel`witness_checkorder                                   7   0.0%
kernel`sse2_pagezero                                        8   0.0%
kernel`strncmp                                              9   0.0%
kernel`spinlock_exit                                       10   0.0%
kernel`_mtx_lock_flags                                     11   0.0%
kernel`witness_unlock                                      15   0.0%
kernel`sched_idletd                                       137   0.3%
0xc10981a5                                              42139  99.3%

This script will also work with kernel modules. To use this feature, run the script with the -m flag:

# ./hotkernel -m
Sampling... Hit Ctrl-C to end.
^C
MODULE                                                  COUNT   PCNT
0xc107882e                                                  1   0.0%
0xc10e6aa4                                                  1   0.0%
0xc1076983                                                  1   0.0%
0xc109708a                                                  1   0.0%
0xc1075a5d                                                  1   0.0%
0xc1077325                                                  1   0.0%
0xc108a245                                                  1   0.0%
0xc107730d                                                  1   0.0%
0xc1097063                                                  2   0.0%
0xc108a253                                                 73   0.0%
kernel                                                    874   0.4%
0xc10981a5                                             213781  99.6%

The procsystime script captures and prints the system call time usage for a given PID or process name. In the following example, a new instance of /bin/csh was spawned. The procsystime was executed and remained waiting while a few commands were typed on the other incarnation of csh. These are the results of this test:

# ./procsystime -n csh
Tracing... Hit Ctrl-C to end...
^C

Elapsed Times for processes csh,

         SYSCALL          TIME (ns)
          getpid               6131
       sigreturn               8121
           close              19127
           fcntl              19959
             dup              26955
         setpgid              28070
            stat              31899
       setitimer              40938
           wait4              62717
       sigaction              67372
     sigprocmask             119091
    gettimeofday             183710
           write             263242
          execve             492547
           ioctl             770073
           vfork            3258923
      sigsuspend            6985124
            read         3988049784

As shown, the read() system call seems to use the most time in nanoseconds with the getpid() system call used the least amount of time.