Performance Tuning for Linux Servers [Electronic resources] نسخه متنی

strace

strace ships with all versions of Linux. strace TRaces all of the system calls from an application and is useful for seeing how a particular application is using the system. Use strace to determine if an application is performing a large number of a particular type of system call, such as reads or writes to a file, memory allocations and frees, task forks and clones, or other system calls. With strace verbose mode enabled, the actual parameters being passed to strace and the results are displayed. You can use verbose mode to verify that the correct parameters are being passed and that the results being passed back are expected. This type of information is useful for debugging a new application or to see what is going on in an application that has been identified as having a problem by a higher-level trace tool.[View full width]

# strace
execve("/piperf/bin/pi_watch", ["pi_watch", "100"], [/* 32 vars */]) = 0
uname({ sys="Linux", node="tpcw.ltc.austin.ibm.com", ...} ) = 0
brk(0) = 0x804a000
old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40016000
open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory)
open("tls/i686/mmx/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
open("tls/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
open("tls/mmx/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
open("tls/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
open("i686/mmx/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
open("i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
open("mmx/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
open("libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/piperf/bin/tls/i686/mmx/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/piperf/bin/tls/i686/mmx", 0xbfffefb0) = -1 ENOENT (No such file or directory)open
("/piperf/bin/tls/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/piperf/bin/tls/i686", 0xbfffefb0) = -1 ENOENT (No such file or directory)
open("/piperf/bin/tls/mmx/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/piperf/bin/tls/mmx", 0xbfffefb0) = -1 ENOENT (No such file or directory)
open("/piperf/bin/tls/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/piperf/bin/tls", 0xbfffefb0) = -1 ENOENT (No such file or directory)
open("/piperf/bin/i686/mmx/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/piperf/bin/i686/mmx", 0xbfffefb0) = -1 ENOENT (No such file or directory)
open("/piperf/bin/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/piperf/bin/i686", 0xbfffefb0) = -1 ENOENT (No such file or directory)
open("/piperf/bin/mmx/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/piperf/bin/mmx", 0xbfffefb0) = -1 ENOENT (No such file or directory)
open("/piperf/bin/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/piperf/bin", { st_mode=S_IFDIR|0777, st_size=4096, ...} ) = 0
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat64(3, { st_mode=S_IFREG|0644, st_size=43183, ...} ) = 0
old_mmap(NULL, 43183, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40017000
close(3) = 0
open("/lib/tls/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0`V\1B4\0"..., 512) = 512
fstat64(3, { st_mode=S_IFREG|0755, st_size=1531064, ...} ) = 0
old_mmap(0x42000000, 1257224, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x42000000
old_mmap(0x4212e000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x12e000) =
0x4212e000
old_mmap(0x42131000, 7944, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1,
0) = 0x42131000
close(3) = 0
set_thread_area({ entry_number:-1 -> 6, base_addr:0x40016a80, limit:1048575, seg_32bit:1,
contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1} ) = 0
munmap(0x40017000, 43183) = 0
write(2, " val = 1724500000\n", 18 val = 1724500000
) = 18
exit_group(0) = ?

The -c option produces a call count report and produces output similar to the following.

# strace c
execve("/piperf/bin/pi_watch", ["pi_watch", "100"], [/* 32 vars */]) = 0
val = 1724500000
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
44.77    0.000124           7        19        17 open
18.77    0.000052           7         8         7 stat64
15.52    0.000043           9         5           old_mmap
4.33    0.000012          12         1           munmap
2.89    0.000008           8         1           read
2.89    0.000008           8         1           write
2.89    0.000008           4         2           fstat64
2.89    0.000008           8         1           set_thread_area
2.17    0.000006           6         1           uname
1.81    0.000005           3         2           close
1.08    0.000003           3         1           brk
------ ----------- ----------- --------- --------- ----------------
100.00    0.000277                    42        24 total

A summary report generated by the c option gives you an idea of what system calls are being made and which system calls are consuming all of the resources. You can then use a more detailed profiler to investigate from where these calls are being made.

You can use an additional parameter to add the timestamp to each call. The timestamp gives a good indication of the relative time when each call took place and whether there is a certain time frame when groups of calls are being made. This information could help narrow down the problem to a specific time frame and set of functions.