Strace Examples, Options & Usage

strace is an important debug tool in Linux and Unix systems to trace system calls and signals. strace is used where the program does not provide sufficient information for the cause of failures and we need to go a level deeper in to system calls and signal levels to find out potential issues.

What strace is used for ?

strace is used to  intercepts the process and displays what system calls are getting executed along with their arguments and status. 

 strace also displays signals which are received by a process during its execution while the strace is on.

strace Syntax : 

stace <programe Name >                                       ### displays the output on the screen

strace -o <outputfileName> <program Name >  ### Redirects strace output to a file.

strace output format :

Strace output is in multiple lines and each line has 

  • The name of each system call in the first column
  • its arguments in the the middle portion enclosed by parenthesis.
  • its return value in the last column

Like :

system_call( arguments ) = return value

as in this example :

open(AT_FDCWD, “/etc/ld.so.cache”, O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=140857, …}) = 0


Strace Error Codes

Strace displays c language error codes, Errors (typically a return value of -1) have the errno symbol and error string appended to it.

Some error symbols and their description.

EPERM  - Operation not permitted
ENOENT - No such file or directory
ESRCH - No such process
EINTR - Interrupted system call
EIO - I/O error
ENXIO - No such device or address
E2BIG - Argument list too long
ENOEXEC - Exec format error
EBADF - Bad file number
ECHILD - No child processes

strace Installation :

strace may not be installed on all system but can be installed if you have permission to install packages, usually root permission.

1. Redhat and similar distributions

yum install strace

2. Debian and similar distributions

apt-get install strace
Here are  examples  with usages of strace command that you can use to debug the programs

 

1. Running strace on a program 

strace can be used with a program or command as argument. The output of the command is displayed on the screen. Given the amount of lines printed it is suggested to put the output in a file to analyses the data using next example.

$strace ls

[root@localhost test]# strace ls
execve("/usr/bin/ls", ["ls"], 0x7ffc2d63c980 /* 37 vars */) = 0
brk(NULL)                               = 0x558247baa000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffe82ba3dc0) = -1 EINVAL (Invalid argument)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=140857, ...}) = 0
mmap(NULL, 140857, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fad64bb8000
close(3)                                = 0
openat(AT_FDCWD, "/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\210\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=188664, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fad64bb6000
...
...
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}) = 0
write(1, "op.sh  test1  testfile1  testfil"..., 39op.sh  test1  testfile1  testfile2  zz
) = 39
close(1)                                = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

2. Send strace output to a file with -o option

It is better to collect the stace date in a file for a analysis.  -o option alloes the strace output to be redirected to file.

$strace -o /tmp/debug.log ls

3. strace a running process and collect its output

strace can take a process id as argument and capture the system call and signal being used.  Get the process id using ps -ef command and use -p option to run strace.

$strace -o /tmp/strace-ps.log  -p 2212  &

$tail -f /tmp/strace-ps.log

4. Get list of system calls used by the program.

This a very important option as strace prints out a lot of information and it becomes difficult to read through line by line.  with -c option you can see which system calls are used, how much time they took  and which one has an error and then you can focus on those system calls as described in next example.

strace -c option gives a list of system calls used by the program.

[root@localhost test]# strace -c ls /tmp/test
op.sh  test1  testfile1  testfile2  zz
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 30.25    0.000549          16        33           mmap
 16.14    0.000293          29        10           mprotect
  8.93    0.000162          18         9           openat
  6.61    0.000120          10        11           close
  5.67    0.000103           7        14           read
  4.52    0.000082           8        10           fstat
  4.19    0.000076          76         1           munmap
  3.97    0.000072          36         2           statfs
  2.37    0.000043           5         8           lseek
  2.15    0.000039          19         2           rt_sigaction
  2.04    0.000037          18         2           getdents64
  1.82    0.000033          16         2           ioctl
  1.76    0.000032          10         3           brk
  1.54    0.000028          28         1           write
  1.38    0.000025          12         2         1 access
  1.27    0.000023          23         1           prlimit64
  1.21    0.000022          22         1           set_tid_address
  1.16    0.000021          21         1           stat
  1.10    0.000020          20         1           set_robust_list
  0.99    0.000018          18         1           rt_sigprocmask
  0.94    0.000017           8         2         1 arch_prctl
  0.00    0.000000           0         1           execve
------ ----------- ----------- --------- --------- ----------------
100.00    0.001815          15       118         2 total

5. filter strace for only one type of system call

-e option can be used to return status of system call in the argument. To see just the openat ( open system call  in some other systems ) system call : 

[root@localhost test]# strace  -e openat  ls /tmp/test 
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/lib64/libcap.so.2", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/lib64/libpcre2-8.so.0", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/lib64/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/lib64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3 openat(AT_FDCWD, "/tmp/test", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3 op.sh test1 testfile1 testfile2 zz +++ exited with 0 +++

Multiple calls can be specified with , separated list as -e syscallA,syscallB

[root@localhost test]# strace  -e openat,close  ls /tmp/test 
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 close(3) = 0 openat(AT_FDCWD, "/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3 close(3) = 0 openat(AT_FDCWD, "/lib64/libcap.so.2", O_RDONLY|O_CLOEXEC) = 3 close(3) = 0

6. Display timestamps for the system calls

time stamps are helpful when a time specific window has to be analyzed.

-t option provides the time stamps for the process system calls.

[root@localhost test]# strace -t   ls /tmp 
00:38:09 execve("/usr/bin/ls", ["ls", "/tmp"], 0x7ffe8df0fe00 /* 37 vars */) = 0 00:38:09 brk(NULL) = 0x56310fba6000 00:38:09 arch_prctl(0x3001 /* ARCH_??? */, 0x7ffc87fd0e20) = -1 EINVAL (Invalid argument) 00:38:09 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) 00:38:09 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 00:38:09 fstat(3, {st_mode=S_IFREG|0644, st_size=140857, ...}) = 0 00:38:09 mmap(NULL, 140857, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa906b5b000 00:38:09 close(3) = 0 00:38:09 openat(AT_FDCWD, "/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3 00:38:09 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\210\0\0\0\0\0\0"..., 832) = 832 00:38:09 fstat(3, {st_mode=S_IFREG|0755, st_size=188664, ...}) = 0 00:38:09 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa906b59000 ... ... 00:38:09 write(1, "aaa\t Temp-2275cbef-7c2f-4517-a"..., 55aaa Temp-2275cbef-7c2f-4517-af1c-adddcb81de95 test ) = 55 00:38:09 write(1, "debug.log Temp-5150a921-0d09-42"..., 81debug.log Temp-5150a921-0d09-423d-90bc-f3ca29cf11d1 tracker-extract-files.1000 ) = 81 00:38:09 close(1) = 0 00:38:09 close(2) = 0 00:38:09 exit_group(0) = ? 00:38:09 +++ exited with 0 +++

7. Display relative time for each system call.

strace with option  -r  print a relative timestamp upon entry to each system call. This records the time difference between the beginning of successive system calls. Default is in microseconds. 

The  measurements can differ from the difference in time reported by the -t option as -r option uses the monotonic clock time for measuring time difference and not the wall clock time

[root@localhost test]# strace -r   ls /tmp 
     0.000000 execve("/usr/bin/ls", ["ls", "/tmp"], 0x7ffc94c600e0 /* 37 vars */) = 0
     0.001646 brk(NULL)                 = 0x560e70c53000
     0.004839 arch_prctl(0x3001 /* ARCH_??? */, 0x7ffd2d697060) = -1 EINVAL (Invalid argument)
     0.000910 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
     0.003056 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
     0.000128 fstat(3, {st_mode=S_IFREG|0644, st_size=140857, ...}) = 0
     0.000103 mmap(NULL, 140857, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa9561f6000
     0.000103 close(3)                  = 0
     0.000116 openat(AT_FDCWD, "/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
     0.000108 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\210\0\0\0\0\0\0"..., 832) = 832
     0.000151 fstat(3, {st_mode=S_IFREG|0755, st_size=188664, ...}) = 0
     0.000099 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa9561f4000
     0.000157 mmap(NULL, 181744, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa9561c7000
     0.000166 mprotect(0x7fa9561ce000, 139264, PROT_NONE) = 0
     ...
     ...     
     0.000174 close(1)                  = 0
     0.000177 close(2)                  = 0
     0.000165 exit_group(0)             = ?
     0.000336 +++ exited with 0 +++

Comments

This site uses Akismet to reduce spam. Learn how your comment data is processed.