FreeBSD Handbook
Prev | Chapter 26 DTrace | Next

# 26.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`.

> Important: At this point it is prudent to remind the reader that DTrace support in FreeBSD is incomplete and experimental. Many of these scripts will not work as they are either too Solaris™-specific or use probes which are unsupported at this time.

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:

    # cd /usr/share/dtrace/toolkit
    # ./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.

Prev | Home | Next
Enabling DTrace Support | Up | The D Language