Strace is a debugging tool that will help you troubleshoot issues. It monitors the system calls and signals of a specific program. It is helpful when you do not have the source code and would like to debug the execution of a program. strace provides you the execution sequence of a binary from start to end.

Here are some strace examples

Trace the Execution of an Executable

You can use strace command to trace the execution of any executable. The following example shows the output of strace for the Linux ls command.

# strace vmstat       
execve("/bin/vmstat", ["vmstat"], [/* 20 vars */]) = 0
brk(0)                                  = 0x1265000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc8d8e34000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
...                  = 0
open("/lib64/libprocps.so.4", 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\0\320G\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=78704, ...}) = 0
...
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc8d8e08000
...
mprotect(0x606000, 4096, PROT_READ)     = 0
...
open("/proc/meminfo", O_RDONLY)         = 3
lseek(3, 0, SEEK_SET)                   = 0
read(3, "MemTotal:       16268500 kB\nMemF"..., 8191) = 1198
open("/proc/stat", O_RDONLY)            = 4
read(4, "cpu  7941688 34562 10662205 8979"..., 65535) = 1435
open("/proc/vmstat", O_RDONLY)          = 5
lseek(5, 0, SEEK_SET)                   = 0
read(5, "nr_free_pages 63412\nnr_alloc_bat"..., 8191) = 2619
write(1, " 1  0  72024 253648    988 11726"..., 83 1  0  72024 253648    988 11726860    0    0  1428  1401    4    0  1  1 97  1  0
) = 83
close(1)                                = 0
munmap(0x7fc8d8e33000, 4096)            = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

Trace a Specific System Calls in an Executable

Be default, strace displays all system calls for the given executable. To display only a specific system call, use the strace -e option as shown below.

For example, if you want to check which configuration a program opens, this is the best option to play with

# strace -e open vmstat 
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib64/libprocps.so.4", O_RDONLY|O_CLOEXEC) = 3
open("/lib64/libsystemd-login.so.0", O_RDONLY|O_CLOEXEC) = 3
...
open("/lib64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
open("/lib64/libattr.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/usr/lib64/elfutils/tls/x86_64/libelf.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
...
open("/lib64/libz.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/sys/devices/system/cpu/online", O_RDONLY|O_CLOEXEC) = 3
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
open("/proc/meminfo", O_RDONLY)         = 3
open("/proc/stat", O_RDONLY)            = 4
open("/proc/vmstat", O_RDONLY)          = 5
 0  0  72024 255612    988 11727036    0    0  1428  1401    4    1  1  1 97  1  0
+++ exited with 0 +++


The above output displays only the open system call of the vmstat command. At the end of the strace output, it also displays the output of the vmstat command.

If you want to trace multiple system calls use the “-e trace=” option. The following example displays both open and read system calls.

# strace -e trace=open,read vmstat 
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib64/libprocps.so.4", 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\0\320G\0\0\0\0\0\0"..., 832) = 832
open("/lib64/libsystemd-login.so.0", 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\0\0\0\0\0\0\0\0\0"..., 832) = 832
...
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320\23\0\0\0\0\0\0"..., 832) = 832
open("/usr/lib64/elfutils/tls/x86_64/libelf.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
...
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p!\0\0\0\0\0\0"..., 832) = 832
open("/sys/devices/system/cpu/online", O_RDONLY|O_CLOEXEC) = 3
read(3, "0-3\n", 8192)                  = 4
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
open("/proc/meminfo", O_RDONLY)         = 3
read(3, "MemTotal:       16268500 kB\nMemF"..., 8191) = 1198
open("/proc/stat", O_RDONLY)            = 4
read(4, "cpu  7942751 34562 10663058 8981"..., 65535) = 1435
open("/proc/vmstat", O_RDONLY)          = 5
read(5, "nr_free_pages 63912\nnr_alloc_bat"..., 8191) = 2619
 0  0  72024 255648    988 11727056    0    0  1428  1401    4    1  1  1 97  1  0
+++ exited with 0 +++

Save the Trace Execution to a File Using Option -o

The following examples stores the strace output to output.txt file.

# strace -o vmstat.output vmstat
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0  72024 255992    988 11726956    0    0  1428  1401    4    1  1  1 97  1  0

run cat vmstat.output, you will see the same output of 'strace vmstat'

Execute Strace on a Running Linux Process Using Option -p

Want to strace a up and running process ?

First, identify the PID of a program using ps command.

For example, if you want to do strace on the mysql that is currently running, identify the PID of the program.

$ ps -C mysql
  PID TTY          TIME CMD
 6803 pts/0    00:00:00 mysql

Use strace -p option as shown below to display the strace for a given process id.

$  sudo strace -p 6803 -o firefox_trace.txt

Now the execution trace of firefox process will be logged into firefox_trace.txt text file. You can tail this text file to watch the live trace of the firefox executable.

Note: Strace will show error if uid doesn't match to the proces uid.


Print Timestamp for Each Trace Output Line Using Option -t

To print the timestamp for each strace output line, use the option -t as shown below.

# strace -t -e open ls /root
11:20:16 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
11:20:16 open("/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
11:20:16 open("/lib64/libcap.so.2", O_RDONLY|O_CLOEXEC) = 3
...
11:20:16 open("/lib64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
11:20:16 open("/proc/filesystems", O_RDONLY) = 3
UcliEvt.log  anaconda-ks.cfg  bin  etc    ks-post-install.log  mysql.output  vmstat.output
11:20:16 +++ exited with 0 +++

To get finer timestamp, use option '-tt' to get microsecond

# strace -tt -e open ls /root

The -ttt displays microseconds like above, but instead of printing surrent time, it displays the number of seconds since the epoch.

# strace -ttt -e open ls /root

Print Relative Time for System Calls Using Option -r

Strace also has the option to print the execution time for each system calls as shown below. This is a really good option for program time cost debugging.

# strace -r -e open ls /root
     0.000000 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
     0.000307 open("/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
...
     0.000971 open("/proc/filesystems", O_RDONLY) = 3
UcliEvt.log  anaconda-ks.cfg  bin  etc    ks-post-install.log  mysql.output  vmstat.output
     0.006395 +++ exited with 0 +++

Generate Statistics Report of System Calls Using Option -c

Using option -c, strace provides useful statistical report for the execution trace. The “calls” column in the following output indicated how many times that particular system call was executed.

# strace -c ls /root
UcliEvt.log  anaconda-ks.cfg  bin  etc    ks-post-install.log  mysql.output  vmstat.output
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 24.26    0.000163           5        30           mmap
 20.54    0.000138           7        20           mprotect
 15.92    0.000107          10        11           open
  9.08    0.000061           6        11           read
  5.65    0.000038           3        14           close
  4.17    0.000028           2        12           fstat
...
  0.60    0.000004           4         1         1 access
  0.45    0.000003           2         2           rt_sigaction
  0.45    0.000003           3         1           execve
  0.15    0.000001           1         1           getrlimit
  0.15    0.000001           1         1           arch_prctl
  0.15    0.000001           1         1           set_tid_address
------ ----------- ----------- --------- --------- ----------------
100.00    0.000672                   122         3 total