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...

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!!!

Leave a Reply

Your email address will not be published. Required fields are marked *