The syscall
provider enables you to trace every system call entry and return. System calls can be a good starting point for understanding a process's behavior, especially if the process seems to be spending a large amount of time executing or blocked in the kernel. You can use the
prstat
(
1M
)
command to see where processes are spending time:
$ prstat -m -p 31337
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/NLWP
13499 user1 53 44 0.0 0.0 0.0 0.0 2.5 0.0 4K 24 9K 0 mystery/6
This example shows that the process 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 use a simple D program specified 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
open 1 lwp_park 2 times 4 fcntl 5 close 6 sigaction 6 read 10 ioctl 14 sigprocmask 106 write 1092
This report shows which system calls are being called most often, in this case, the
write
(
2
)
system call. You can use the syscall
provider to further examine the source of all the write
system calls:
# dtrace -n syscall::write:entry'/pid == 31337/{ @writes[arg2] = quantize(); }'
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 2048 | 0
The output shows that the process is executing many write
system calls with a relatively small amount of data. This ratio could be the source of the performance problem for this particular process. This example illustrates a general methodology for investigating system call behavior.