1This is a demonstration of the procsystime tool, which can give details
2on how processes make use of system calls.
3
4Here we run procsystime on processes which have the name "bash",
5
6   #  procsystime -n bash
7   Hit Ctrl-C to stop sampling...
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
21By default procsystime prints elapsed times, the time from when the syscall
22was issued to it's completion. In the above output, we can see the read()
23syscall took the most time for this process - 8.57 seconds for all the
24reads combined. This is because the read syscall is waiting for keystrokes.
25
26
27
28Here we try the "-o" option to print CPU overhead times on "bash",
29
30   # procsystime -o -n bash
31   Hit Ctrl-C to stop sampling...
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
45This identifies which syscall type from bash is consuming the most CPU time.
46This is ioctl, at 932 microseconds. Compare this output to the default in
47the first example - both are useful for different reasons, this CPU overhead
48output helps us see why processes are consuming a lot of sys time.
49
50
51
52This demonstrates using the "-a" for all details, this time with "ssh",
53
54   # procsystime -a -n ssh
55   Hit Ctrl-C to stop sampling...
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
82Now we can see elapsed times, overhead times, and syscall counts in one
83report. Very handy. We can also see totals printed as "TOTAL:".
84
85
86
87procsystime also lets us just examine one PID. For example,
88
89   # procsystime -p 1304
90   Hit Ctrl-C to stop sampling...
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
105Here is a longer example of running procsystime on mozilla,
106
107   # procsystime -a -n mozilla-bin
108   Hit Ctrl-C to stop sampling...
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
150
151
152