Difference between revisions of "Strace: what a process does"

From Linuxintro
imported>ThorstenStaerk
imported>ThorstenStaerk
Line 15: Line 15:
 
  syscall(arguments) = return value
 
  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.
+
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 [http://linux.die.net/man/2/clock_gettime man 2 clock_gettime]. It retrieves the current time.
  
−
The above example consists of 4 lines that can be analyzed like this:
+
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:
−
open("/lib64/libexpat.so.1", O_RDONLY)  = 6                                                 
+
ll /proc/5314/fd/12
−
This first line performs the [http://man-wiki.net/index.php/2:open 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 [http://man-wiki.net/index.php/2:open man 2 open].
+
  lrwx------ 1 root root 64 Apr 19 06:44 /proc/5314/fd/12 -> socket:[73910]
−
  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 [http://man-wiki.net/index.php/2:read 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.
+
Ok, to find out what socket:[73910] is we use the command
−
fstat(6, {st_mode=S_IFREG|0755, st_size=170240, ...}) = 0   
+
  lsof | grep 73910
−
Here, [http://man-wiki.net/index.php/2:fstat 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 [http://man-wiki.net/index.php/2:mmap 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 =
 
= Search for a syscall =

Revision as of 05:02, 19 April 2014

strace is a command to show what a command or process is doing.

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.

See also

Retrieved from "http://linuxintro.org/index.php?title=Strace:_what_a_process_does&oldid=14352"