DTrace scripts consist of a list of one or more probes, or instrumentation points, where each probe is associated with an action. Whenever the condition for a probe is met, the associated action is executed. For example, an action may occur when a file is opened, a process is started, or a line of code is executed. The action might be to log some information or to modify context variables. The reading and writing of context variables allows probes to share information and to cooperatively analyze the correlation of different events.
To view all probes, the administrator can execute the following command:
dtrace -l | more
Each probe has an
PROVIDER (dtrace or fbt), a
MODULE, and a
FUNCTION NAME. Refer to dtrace(1) for
more information about this command.
The examples in this section provide an overview of how to
use two of the fully supported scripts from the
DTrace Toolkit: the
hotkernel script is designed to
identify which function is using the most kernel time. It will
produce output similar to the following:
./hotkernelSampling... Hit Ctrl-C to end.
As instructed, 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
./hotkernel -mSampling... 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%
procsystime script captures and
prints the system call time usage for a given process
ID (PID) or process name.
In the following example, a new instance of
/bin/csh was spawned. Then,
procsystime was executed and remained
waiting while a few commands were typed on the other incarnation
csh. These are the results of this
./procsystime -n cshTracing... 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 used
the most time in nanoseconds while the
getpid() system call used the least amount