Strace: what a process does
strace is a command to show what a command or process is doing.
Contents
Analyzing strace's output
To analyze strace's output 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:
clock_gettime(CLOCK_MONOTONIC, {4433, 764347636}) = 0
poll([{fd=12, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 1 ([{fd=12, revents=POLLIN|POLLRDNORM}])
recv(12, "\37\36&\364T<\264\6Og\20\2\30%-\31C\3757\350{\260\0203\351\23&O\365(y\212"..., 16384, 0) = 1448
analysis
Every line follows the syntax
syscall(arguments) = return value
The meaning of the syscall, its expected arguments and its return value can be determined from its man page. For example to understand the first line call man 2 clock_gettime. It retrieves the current time.
Wow, that was easy. Now to the next line, poll. According to [man 2 poll http://linux.die.net/man/2/poll] it waits for an event on a file descriptor, like "data to be read". The file descriptor is the first argument, 12. What's this? Let's assume the process ID we are tracing is 5314. Then we can find out the file descriptor like this:
ll /proc/5314/fd/12 lrwx------ 1 root root 64 Apr 19 06:44 /proc/5314/fd/12 -> socket:[73910]
Ok, to find out what socket:[73910] is we use the command
lsof | grep 73910
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. This can be used e.g. to find out where configuration changes are stored.
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.
