Measuring system call time with procsystime


When debugging application performance problems related to high system time, I typically start my analysis by watching the system calls the application is issuing, and measuring how much time is spent in each system call. Gathering this information is simple with DTrace syscall provider, and the DTraceToolkit comes with the procsystime script to allow admins to easily analyze system call behavior. To use procsystime to measure how much time the sshd proceses are spending in each system call, we can run procsystime with the “-T” option to get the total time spent in all system calls, the “-n” option, and the process name to analyze (in the example below, using the string “sshd” will cause procsystime to analyze the system call behavior for all processes named sshd):

$ procsystime -Tn sshd

Hit Ctrl-C to stop sampling...
^C

Elapsed Times for processes sshd,

SYSCALL TIME (ns)
umask 9804
setpgrp 12111
nfs 12194
pathconf 12973
chdir 13656
setregid 20676
setreuid 22364
getdents64 27036
getgroups 28605
lwp_self 29808
getsockopt 30959
setgid 31365
alarm 31507
zone 31691
setuid 33861
setsockopt 39311
setegid 39660
setcontext 40061
seteuid 40149
lseek 41430
dup 43978
c2audit 44604
getsockname 51978
privsys 52974
waitsys 56247
getgid 57050
accept 59959
fsat 76925
setgroups 79791
tasksys 81609
systeminfo 91019
sysconfig 112749
recvfrom 127964
access 138435
pipe 144371
getpeername 157330
fxstat 175541
schedctl 182224
vfork 217932
putmsg 241482
connect 301860
sigaction 317411
shutdown 328316
brk 356044
so_socket 409152
getpid 484735
fcntl 494322
gtime 526637
stat64 539840
llseek 624945
resolvepath 678157
open64 715602
getuid 950119
fstat64 964132
ioctl 1171727
xstat 1278052
memcntl 1394735
send 1846685
close 2325223
open 2685141
mmap 5289087
munmap 5379678
lwp_sigmask 6178493
exece 11787526
doorfs 28604988
write 46083911
fork1 57233817
read 96877372
pollsys 25533333727
TOTAL: 25811904817

The output will contain the name of the system call in the left hand column, and the time spent in that system call in the right hand column. There are additional options to display the number of calls to each system call, and you can also filter by process id if you want to measure a specific process. If you are running Solaris 10 and haven’t downloaded the DTraceToolkit, I highly recommend doing so!!!

This article was posted by Matty on 2007-03-17 10:47:00 -0400 EDT