strace

team bbl


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.

Some typical uses of strace are to determine if the blocking factor for disk I/O is correct and optimal. You can see if memory is constantly being allocated and freed as opposed to the allocation of a buffer pool and the reuse of buffers. For example, if threads are constantly being forked or cloned and then freed, you can investigate a method of reusing existing threads to reduce the overhead of the thread creates and frees. You can also use threads to validate that the parameters (such as addresses or buffer sizes) that are being passed on system calls are correct.

The only drawback of the strace tool is that you must measure the application from its startup until the time the application terminates or you kill it. You cannot start tracing in the middle of the application and end tracing without ending the application.

See the info strace command for more information.

The following is a sample strace report.

[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.

    team bbl



    Performance Tuning for Linux Servers
    Performance Tuning for Linux Servers
    ISBN: 0137136285
    EAN: 2147483647
    Year: 2006
    Pages: 254

    flylib.com © 2008-2017.
    If you may any questions please contact us: flylib@qtcs.net