mirror of
https://github.com/brendangregg/perf-tools.git
synced 2025-11-30 23:16:03 +07:00
298 lines
9.0 KiB
Plaintext
298 lines
9.0 KiB
Plaintext
Demonstrations of syscount, the Linux perf_events version.
|
|
|
|
|
|
The first mode I use is "-c", where it behaves like "strace -c", but for the
|
|
entire system (all procesess) and with much lower overhead:
|
|
|
|
# ./syscount -c
|
|
Tracing... Ctrl-C to end.
|
|
^Csleep: Interrupt
|
|
SYSCALL COUNT
|
|
accept 1
|
|
getsockopt 1
|
|
setsid 1
|
|
chdir 2
|
|
getcwd 2
|
|
getpeername 2
|
|
getsockname 2
|
|
setgid 2
|
|
setgroups 2
|
|
setpgid 2
|
|
setuid 2
|
|
getpgrp 4
|
|
getpid 4
|
|
rename 4
|
|
setitimer 4
|
|
setrlimit 4
|
|
setsockopt 4
|
|
statfs 4
|
|
set_tid_address 5
|
|
readlink 6
|
|
set_robust_list 6
|
|
nanosleep 7
|
|
newuname 7
|
|
faccessat 8
|
|
futex 10
|
|
clock_gettime 16
|
|
newlstat 20
|
|
pipe 20
|
|
epoll_wait 24
|
|
getrlimit 25
|
|
socket 27
|
|
connect 29
|
|
exit_group 30
|
|
getppid 31
|
|
dup2 34
|
|
wait4 51
|
|
fcntl 58
|
|
getegid 72
|
|
getgid 72
|
|
getuid 72
|
|
geteuid 75
|
|
perf_event_open 100
|
|
munmap 121
|
|
gettimeofday 216
|
|
access 266
|
|
ioctl 340
|
|
poll 348
|
|
sendto 374
|
|
mprotect 414
|
|
brk 597
|
|
rt_sigaction 632
|
|
recvfrom 664
|
|
lseek 749
|
|
newfstatat 2922
|
|
openat 2925
|
|
newfstat 3229
|
|
newstat 4334
|
|
open 4534
|
|
fchdir 5845
|
|
getdents 5854
|
|
read 7673
|
|
close 7728
|
|
select 9633
|
|
rt_sigprocmask 19886
|
|
write 34581
|
|
|
|
While tracing, the write() syscall was executed 34,581 times.
|
|
|
|
This mode uses "perf stat" to count the syscalls:* tracepoints in-kernel.
|
|
|
|
|
|
You can add a duration (-d) and limit the number shown (-t):
|
|
|
|
# ./syscount -cd 5 -t 10
|
|
Tracing for 5 seconds. Top 10 only...
|
|
SYSCALL COUNT
|
|
gettimeofday 1009
|
|
write 3583
|
|
read 8174
|
|
openat 21550
|
|
newfstat 21558
|
|
open 21824
|
|
fchdir 43098
|
|
getdents 43106
|
|
close 43694
|
|
newfstatat 110936
|
|
|
|
While tracing for 5 seconds, the newfstatat() syscall was executed 110,936
|
|
times.
|
|
|
|
|
|
Without the -c, syscount shows syscalls by process name:
|
|
|
|
# ./syscount -d 5 -t 10
|
|
Tracing for 5 seconds. Top 10 only...
|
|
[ perf record: Woken up 66 times to write data ]
|
|
[ perf record: Captured and wrote 16.513 MB perf.data (~721455 samples) ]
|
|
COMM COUNT
|
|
stat 450
|
|
perl 537
|
|
catalina.sh 1700
|
|
postgres 2094
|
|
run 2362
|
|
:6946 4764
|
|
ps 5961
|
|
sshd 45796
|
|
find 61039
|
|
|
|
So processes named "find" called 61,039 syscalls during the 5 seconds of
|
|
tracing.
|
|
|
|
Note that this mode writes a perf.data file. This is higher overhead for a
|
|
few reasons:
|
|
|
|
- all data is passed from kernel to user space, which eats CPU for the memory
|
|
copy. Note that it is buffered in an efficient way by perf_events, which
|
|
wakes up and context switches only a small number of times: 66 in this case,
|
|
to hand 16 Mbytes of trace data to user space.
|
|
- data is post-processed in user space, eating more CPU.
|
|
- data is stored on the file system in the perf.data file, consuming available
|
|
storage.
|
|
|
|
This will be improved in future kernels, but it is difficult to improve this
|
|
much further in existing kernels. For example, using a pipe to "perf script"
|
|
instead of writing perf.data can have issues with feedback loops, where
|
|
perf traces itself. This syscount version goes to lengths to avoid tracing
|
|
its own perf, but
|
|
right now with existing functionality in older kernels. The trip via perf.data
|
|
is necessary
|
|
|
|
|
|
Running without options shows syscalls by process name until Ctrl-C:
|
|
|
|
# ./syscount
|
|
Tracing... Ctrl-C to end.
|
|
^C[ perf record: Woken up 39 times to write data ]
|
|
[ perf record: Captured and wrote 9.644 MB perf.data (~421335 samples) ]
|
|
COMM COUNT
|
|
apache2 8
|
|
apacheLogParser 13
|
|
platformservice 16
|
|
snmpd 16
|
|
ntpd 21
|
|
multilog 66
|
|
supervise 84
|
|
dirname 102
|
|
echo 102
|
|
svstat 108
|
|
cut 111
|
|
bash 113
|
|
grep 132
|
|
xargs 132
|
|
redis-server 190
|
|
sed 192
|
|
setuidgid 294
|
|
stat 450
|
|
perl 537
|
|
catalina.sh 1275
|
|
postgres 1736
|
|
run 2352
|
|
:7396 4527
|
|
ps 5925
|
|
sshd 20154
|
|
find 28700
|
|
|
|
Note again it is writing a perf.data file to do this.
|
|
|
|
|
|
The -v option adds process IDs:
|
|
|
|
# ./syscount -v
|
|
Tracing... Ctrl-C to end.
|
|
^C[ perf record: Woken up 48 times to write data ]
|
|
[ perf record: Captured and wrote 12.114 MB perf.data (~529276 samples) ]
|
|
PID COMM COUNT
|
|
3599 apacheLogParser 3
|
|
7977 xargs 3
|
|
7982 supervise 3
|
|
7993 xargs 3
|
|
3575 apache2 4
|
|
1311 ntpd 6
|
|
3135 postgres 6
|
|
3600 apacheLogParser 6
|
|
3210 platformservice 8
|
|
6503 sshd 9
|
|
7978 :7978 9
|
|
7994 run 9
|
|
7968 :7968 11
|
|
7984 run 11
|
|
1451 snmpd 16
|
|
3040 svscan 17
|
|
3066 postgres 17
|
|
3133 postgres 24
|
|
3134 postgres 24
|
|
3136 postgres 24
|
|
3061 multilog 29
|
|
3055 supervise 30
|
|
7979 bash 31
|
|
7977 echo 34
|
|
7981 dirname 34
|
|
7993 echo 34
|
|
7968 svstat 36
|
|
7984 svstat 36
|
|
7975 cut 37
|
|
7991 cut 37
|
|
9857 bash 37
|
|
7967 :7967 40
|
|
7983 run 40
|
|
7972 :7972 41
|
|
7976 xargs 41
|
|
7988 run 41
|
|
7992 xargs 41
|
|
7969 :7969 42
|
|
7976 :7976 42
|
|
7985 run 42
|
|
7992 run 42
|
|
7973 :7973 43
|
|
7974 :7974 43
|
|
7989 run 43
|
|
7990 run 43
|
|
7973 grep 44
|
|
7989 grep 44
|
|
7975 :7975 45
|
|
7991 run 45
|
|
7970 :7970 51
|
|
7986 run 51
|
|
7981 catalina.sh 52
|
|
7974 sed 64
|
|
7990 sed 64
|
|
3455 postgres 66
|
|
7971 :7971 66
|
|
7987 run 66
|
|
7966 :7966 96
|
|
7966 setuidgid 98
|
|
3064 redis-server 110
|
|
7970 stat 150
|
|
7986 stat 150
|
|
7969 perl 179
|
|
7985 perl 179
|
|
7982 run 341
|
|
7966 catalina.sh 373
|
|
7980 postgres 432
|
|
7972 ps 1971
|
|
7988 ps 1983
|
|
9832 sshd 37511
|
|
7979 find 51040
|
|
|
|
Once you've found a process ID of interest, you can use "-c" and "-p PID" to
|
|
show syscall names. This also switches to "perf stat" mode for in-kernel
|
|
counts, and lower overhead:
|
|
|
|
# ./syscount -cp 7979
|
|
Tracing PID 7979... Ctrl-C to end.
|
|
^CSYSCALL COUNT
|
|
brk 10
|
|
newfstat 2171
|
|
open 2171
|
|
newfstatat 2175
|
|
openat 2175
|
|
close 4346
|
|
fchdir 4346
|
|
getdents 4351
|
|
write 25482
|
|
|
|
So the most frequent syscall by PID 7979 was write().
|
|
|
|
|
|
Use -h to print the USAGE message:
|
|
|
|
# ./syscount -h
|
|
USAGE: syscount [-chv] [-t top] {-p PID|-d seconds|command}
|
|
syscount # count by process name
|
|
-c # show counts by syscall name
|
|
-h # this usage message
|
|
-v # verbose: shows PID
|
|
-p PID # trace this PID only
|
|
-d seconds # duration of trace
|
|
-t num # show top number only
|
|
command # run and trace this command
|
|
eg,
|
|
syscount # syscalls by process name
|
|
syscount -c # syscalls by syscall name
|
|
syscount -d 5 # trace for 5 seconds
|
|
syscount -cp 923 # syscall names for PID 923
|
|
syscount -c ls # syscall names for "ls"
|
|
|
|
See the man page and example file for more info.
|