wiki'd

by JoKeru

Using strace to monitor System Calls

[cc lang='bash']
# execute a process via "strace"
\$ strace sleep 1
execve("/bin/sleep", ["sleep", "1"], [/* 17 vars */]) = 0
brk(0) = 0x753000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f74b3eea000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=15637, ...}) = 0
mmap(NULL, 15637, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f74b3ee6000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\355\1\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1437064, ...}) = 0
mmap(NULL, 3545160, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f74b396d000
mprotect(0x7f74b3ac6000, 2093056, PROT_NONE) = 0
mmap(0x7f74b3cc5000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x158000) = 0x7f74b3cc5000
mmap(0x7f74b3cca000, 18504, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f74b3cca000
close(3) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f74b3ee5000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f74b3ee4000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f74b3ee3000
arch_prctl(ARCH_SET_FS, 0x7f74b3ee4700) = 0
mprotect(0x7f74b3cc5000, 16384, PROT_READ) = 0
mprotect(0x7f74b3eec000, 4096, PROT_READ) = 0
munmap(0x7f74b3ee6000, 15637) = 0
brk(0) = 0x753000
brk(0x774000) = 0x774000
open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=1527584, ...}) = 0
mmap(NULL, 1527584, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f74b3d6e000
close(3) = 0
nanosleep({1, 0}, NULL) = 0
close(1) = 0
close(2) = 0
exit_group(0) = ?
[/cc]

[cc lang="bash"]
# attach "strace" to an already running process (squid) and count time, calls, and errors for each system call
\$ strace -p 14331 -c
Process 14331 attached - interrupt to quit
\^CProcess 14331 detached
% time seconds usecs/call calls errors syscall

27.94 0.000266 0 20842 write
21.22 0.000202 0 17188 4188 read
17.86 0.000170 0 7690 close
10.92 0.000104 0 34009 epoll_ctl
5.57 0.000053 0 3288 3288 connect
4.41 0.000042 0 31240 fcntl
4.31 0.000041 0 6217 1695 accept
2.42 0.000023 0 3288 socket
2.10 0.000020 0 3979 stat
1.37 0.000013 0 4522 getsockname
1.05 0.000010 0 3288 bind
0.84 0.000008 0 3288 setsockopt
0.00 0.000000 0 138 sendto
0.00 0.000000 0 236 100 recvfrom
0.00 0.000000 0 3273 getsockopt
0.00 0.000000 0 766 epoll_wait

100.00 0.000952 143252 9271 total
# we have some errors !

# get all "connect" system calls
\$ strace -p 14331 -e connect
Process 14331 attached - interrupt to quit
connect(341, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.226.73")}, 16) = -1 EINPROGRESS (Operation now in progress)
connect(113, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("74.125.226.91")}, 16) = -1 EINPROGRESS (Operation now in progress)
connect(510, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("23.67.61.123")}, 16) = -1 EINPROGRESS (Operation now in progress)
connect(511, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("23.67.61.88")}, 16) = -1 EINPROGRESS (Operation now in progress)
connect(294, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("107.23.19.53")}, 16) = -1 EINPROGRESS (Operation now in progress)
connect(296, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("98.139.225.42")}, 16) = -1 EINPROGRESS (Operation now in progress)
connect(302, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("50.116.194.24")}, 16) = -1 EINPROGRESS (Operation now in progress)
connect(340, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("23.195.83.167")}, 16) = -1 EINPROGRESS (Operation now in progress)
connect(371, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("69.25.24.23")}, 16) = -1 EINPROGRESS (Operation now in progress)
connect(565, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("107.20.232.185")}, 16) = -1 EINPROGRESS (Operation now in progress)
# EINPROGRESS is not really an error, the socket is non-blocking and the connection could not be established immediately (takes time because of the TCP 3-way handshake)

# get all "recvfrom" system calls
\$ strace -p 14331 -e recvfrom
Process 14331 attached - interrupt to quit
recvfrom(7, "a\276\201\200\0\1\0\4\0\0\0\0\3cdn\6blinkx\3com\0\0\1\0\1"..., 16384, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 134
recvfrom(7, "1\331\201\200\0\1\0\v\0\0\0\0\10profiles\6google\3com"..., 16384, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 213
recvfrom(7, 0x7f5a545115c0, 16384, 0, 0x7fffca3fde00, 0x7fffca3fddfc) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(7, "\330\240\201\200\0\1\0\1\0\0\0\0\fachicreceipt\3com\0\0\1"..., 16384, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 50
recvfrom(7, 0x7f5a545115c0, 16384, 0, 0x7fffca3fde00, 0x7fffca3fddfc) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(7, "5\320\201\200\0\1\0\1\0\0\0\0\10tps10201\fdoubleveri"..., 16384, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 59
recvfrom(7, 0x7f5a545115c0, 16384, 0, 0x7fffca3fde00, 0x7fffca3fddfc) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(7, "6\3\201\200\0\1\0\1\0\0\0\0\6ewr-37\10ewr-rtb1\6rfi"..., 16384, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, [16]) = 60
# EAGAIN is not really an error, the socket is non-blocking and there's no data to consume at that particular moment
[/cc]

more details: https://blogs.oracle.com/ksplice/entry/strace_the_sysadmin_s_microscope

Comments