cddl/contrib/dtracetoolkit/Examples/procsystime_example.txt

   1 This is a demonstration of the procsystime tool, which can give details
   2 on how processes make use of system calls.
   3
   4 Here we run procsystime on processes which have the name "bash",
   5
   6    #  procsystime -n bash
   7    Tracing... Hit Ctrl-C to end...
   8    ^C
   9
  10    Elapsed Times for process bash,
  11
  12             SYSCALL          TIME (ns)
  13             setpgrp              27768
  14               gtime              28692
  15         lwp_sigmask             148074
  16               write             235814
  17           sigaction             553556
  18               ioctl             776691
  19                read          857401243
  20
  21 By default procsystime prints elapsed times, the time from when the syscall
  22 was issued to it's completion. In the above output, we can see the read()
  23 syscall took the most time for this process - 8.57 seconds for all the
  24 reads combined. This is because the read syscall is waiting for keystrokes.
  25
  26
  27
  28 Here we try the "-o" option to print CPU overhead times on "bash",
  29
  30    # procsystime -o -n bash
  31    Tracing... Hit Ctrl-C to end...
  32    ^C
  33
  34    CPU Times for process bash,
  35
  36             SYSCALL          TIME (ns)
  37             setpgrp               6994
  38               gtime               8054
  39         lwp_sigmask              33865
  40                read             154895
  41           sigaction             259899
  42               write             343825
  43               ioctl             932280
  44
  45 This identifies which syscall type from bash is consuming the most CPU time.
  46 This is ioctl, at 932 microseconds. Compare this output to the default in
  47 the first example - both are useful for different reasons, this CPU overhead
  48 output helps us see why processes are consuming a lot of sys time.
  49
  50
  51
  52 This demonstrates using the "-a" for all details, this time with "ssh",
  53
  54    # procsystime -a -n ssh
  55    Tracing... Hit Ctrl-C to end...
  56    ^C
  57
  58    Elapsed Times for processes ssh,
  59
  60             SYSCALL          TIME (ns)
  61                read             115833
  62               write             302419
  63             pollsys          114616076
  64              TOTAL:          115034328
  65
  66    CPU Times for processes ssh,
  67
  68             SYSCALL          TIME (ns)
  69                read              82381
  70             pollsys             201818
  71               write             280390
  72              TOTAL:             564589
  73
  74    Syscall Counts for processes ssh,
  75
  76             SYSCALL              COUNT
  77                read                  4
  78               write                  4
  79             pollsys                  8
  80              TOTAL:                 16
  81
  82 Now we can see elapsed times, overhead times, and syscall counts in one
  83 report. Very handy. We can also see totals printed as "TOTAL:".
  84
  85
  86
  87 procsystime also lets us just examine one PID. For example,
  88
  89    # procsystime -p 1304
  90    Tracing... Hit Ctrl-C to end...
  91    ^C
  92
  93    Elapsed Times for PID 1304,
  94
  95             SYSCALL          TIME (ns)
  96               fcntl               7323
  97             fstat64              21349
  98               ioctl             190683
  99                read             238197
 100               write            1276169
 101             pollsys         1005360640
 102
 103
 104
 105 Here is a longer example of running procsystime on mozilla,
 106
 107    # procsystime -a -n mozilla-bin
 108    Tracing... Hit Ctrl-C to end...
 109    ^C
 110
 111    Elapsed Times for processes mozilla-bin,
 112
 113             SYSCALL          TIME (ns)
 114               readv             677958
 115              writev            1159088
 116               yield            1298742
 117                read           18019194
 118               write           35679619
 119               ioctl          108845685
 120            lwp_park        38090969432
 121             pollsys        65955258781
 122              TOTAL:       104211908499
 123
 124    CPU Times for processes mozilla-bin,
 125
 126             SYSCALL          TIME (ns)
 127               yield             120345
 128               readv             398046
 129              writev            1117178
 130            lwp_park            8591428
 131                read            9752315
 132               write           29043460
 133               ioctl           37089349
 134             pollsys          189933470
 135              TOTAL:          276045591
 136
 137    Syscall Counts for processes mozilla-bin,
 138
 139             SYSCALL              COUNT
 140              writev                  3
 141               yield                  9
 142               readv                 58
 143            lwp_park                280
 144               write               1317
 145                read               1744
 146             pollsys               8268
 147               ioctl              16434
 148              TOTAL:              28113
 149