Strace: what a process does
strace is a command to show what a command or process is doing.
Contents
Analyzing strace's output
Analyzing strace's output is tedious if you do not know how it goes. You must know that the first keyword in a line of output from strace is always a syscall like open or read. Then, in parantheses, the arguments follow, then the result. The meaning of the syscall and its parameters and results can be found with the command
man 2 syscall
output
Here is an example output from strace that we are going to analyze:
open("/lib64/libexpat.so.1", O_RDONLY) = 6
read(6, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@>\0\0\0\0\0\0"..., 832) = 832
fstat(6, {st_mode=S_IFREG|0755, st_size=170240, ...}) = 0
mmap(NULL, 2265264, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 6, 0) = 0x7f5d5ced6000
analysis
The above example consists of 4 lines that can be analyzed like this:
open("/lib64/libexpat.so.1", O_RDONLY) = 6
This first line performs the syscall open on the file /lib64/libexpat.so.1. The file shall be opened read-only (O_RDONLY). This call returns the file descriptor 6. /lib64/libexpat.so.1 is now file number 6. You can get this information from man 2 open.
read(6, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@>\0\0\0\0\0\0"..., 832) = 832
The above line reads from the file number 6. The file content is character 177, then the string ELF, then character 2, 1, 1, 0 and so on.
fstat(6, {st_mode=S_IFREG|0755, st_size=170240, ...}) = 0
Here, fstat tells that file number 6 (/lib64/libexpat.so.1) is a regular file.
mmap(NULL, 2265264, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 6, 0) = 0x7f5d5ced6000
The above line performs the syscall mmap. See man 2 mmap about the parameters - if you do you will find out that the file with descriptor number 6 is mapped to memory at address 0x7f5d5ced6000.
Search for a syscall
With strace, you can search for a special syscall. For example,
strace -e open command
will show you all files that have been touched (opened) by command.
Performance analysis
With strace, you can find out the biggest time-consuming syscalls during a program run:
strace -c ls -R Entries Repository Root % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 67.09 0.412153 14 29664 getdents64 27.70 0.170168 11 14849 14 open 4.24 0.026043 0 123740 write 0.72 0.004443 0 14837 close 0.20 0.001204 0 14836 fstat 0.05 0.000285 285 1 execve 0.00 0.000000 0 12 read 0.00 0.000000 0 4 3 stat 0.00 0.000000 0 33 mmap 0.00 0.000000 0 18 mprotect 0.00 0.000000 0 4 munmap 0.00 0.000000 0 12 brk 0.00 0.000000 0 2 rt_sigaction 0.00 0.000000 0 1 rt_sigprocmask 0.00 0.000000 0 2 ioctl 0.00 0.000000 0 1 1 access 0.00 0.000000 0 3 mremap 0.00 0.000000 0 1 fcntl 0.00 0.000000 0 1 getrlimit 0.00 0.000000 0 1 statfs 0.00 0.000000 0 1 arch_prctl 0.00 0.000000 0 3 1 futex 0.00 0.000000 0 1 set_tid_address 0.00 0.000000 0 8 fadvise64 0.00 0.000000 0 1 set_robust_list ------ ----------- ----------- --------- --------- ---------------- 100.00 0.614296 198036 19 total
Now you go
man 2 getdents64
to find out what that syscall is about.
