20 C
Jaipur
Thursday, January 21, 2021

How to Trace Program Execution Using Linux Strace Command

Must read

The strace is a powerful command-line tool for process monitoring, diagnostic and troubleshooting programs in Linux. Generally, it is used to intercept and record the system calls and the signals received by a process. You can use strace to analyze how a program interacts with the system to debug any program.

This tool is very useful if the program continually crashes, or does not behave as expected. It provides deep insight into how the system operates. Any user may trace their own running processes.

In this tutorial, we will show you how to use the strace command-line tool on Linux.

Install Strace

By default, strace is available in the default repository of all Linux operating systems.

On Debian and Ubuntu operating systems, install the strace with the following command:

apt-get install strace -y

On RHEL and CentOS operating systems, install the strace with the following command:

dnf install strace -y

After installing strace, you can verify the strace version using the following command:

strace -V

You should get the following output:

strace -- version 4.8

You can print all options available with strace command with the following command:

strace -help
Output
usage: strace [-CdffhiqrtttTvVxxy] [-I n] [-e expr]...
              [-a column] [-o file] [-s strsize] [-P path]...
              -p pid... / [-D] [-E var=val]... [-u username] PROG [ARGS]
   or: strace -c[df] [-I n] [-e expr]... [-O overhead] [-S sortby]
              -p pid... / [-D] [-E var=val]... [-u username] PROG [ARGS]
-c -- count time, calls, and errors for each syscall and report summary
-C -- like -c but also print regular output
-d -- enable debug output to stderr
-D -- run tracer process as a detached grandchild, not as parent
-f -- follow forks, -ff -- with output into separate files
-i -- print instruction pointer at time of syscall
-q -- suppress messages about attaching, detaching, etc.
-r -- print relative timestamp, -t -- absolute timestamp, -tt -- with usecs
-T -- print time spent in each syscall
-v -- verbose mode: print unabbreviated argv, stat, termios, etc. args
-x -- print non-ascii strings in hex, -xx -- print all strings in hex
-y -- print paths associated with file descriptor arguments
-h -- print help message, -V -- print version
-a column -- alignment COLUMN for printing syscall results (default 40)
-b execve -- detach on this syscall
-e expr -- a qualifying expression: option=[!]all or option=[!]val1[,val2]...
   options: trace, abbrev, verbose, raw, signal, read, write
-I interruptible --
   1: no signals are blocked
   2: fatal signals are blocked while decoding syscall (default)
   3: fatal signals are always blocked (default if '-o FILE PROG')
   4: fatal signals and SIGTSTP (^Z) are always blocked
      (useful to make 'strace -o FILE PROG' not stop on ^Z)
-o file -- send trace output to FILE instead of stderr
-O overhead -- set overhead for tracing syscalls to OVERHEAD usecs
-p pid -- trace process with process id PID, may be repeated
-s strsize -- limit length of print strings to STRSIZE chars (default 32)
-S sortby -- sort syscall counts by: time, calls, name, nothing (default time)
-u username -- run command as username handling setuid and/or setgid
-E var=val -- put var=val in the environment for command
-E var -- remove var from the environment for command
-P path -- trace accesses to path

1. Trace a System Calls

If you want to trace the system calls of the command ls, run the following command:

strace ls file1.txt
Output
execve("/bin/ls", ["ls", "file1.txt"], [/* 61 vars */]) = 0
brk(0)                                  = 0x1f2a000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4dd0d30000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=114633, ...}) = 0
mmap(NULL, 114633, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f4dd0d14000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "177ELF2113>1["..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=134296, ...}) = 0
mmap(NULL, 2238192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f4dd08ed000
mprotect(0x7f4dd090d000, 2093056, PROT_NONE) = 0
mmap(0x7f4dd0b0c000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1f000) = 0x7f4dd0b0c000
mmap(0x7f4dd0b0e000, 5872, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f4dd0b0e000
NLY|O_CLOEXEC) = 3
MAP_DENYWRITE, 3, 0x2000) = 0x7f4dd00e0000
close(3)                                = 0
.......
.......
)             = 10
close(1)                                = 0
munmap(0x7f4dd0d2f000, 4096)            = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

In the above output, you can see the system call and result of the call of ls command. You should also see that exit status is 0. That means there was no error.

One use of strace (Except debugging some problem) is that you can find out which configuration files are read by a program.

For example:

strace php 2>&1 | grep php.ini

2. Filter Specific System Calls

Be default, strace displays all system calls for the given executable. If you want to display only a specific system call, you can use strace -e option.

For example, to displays only the write system call of the ls command run the following command:

strace -e write ls file1.txt file2.txt
Output
write(1, "file1.txt  file2.txtn", 21file1.txt  file2.txt
)  = 21
+++ exited with 0 +++

To displays only the open system call of the ls command run the following command:

strace -e open ls file1.txt file2.txt
Output
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libacl.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libpcre.so.3", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libattr.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/proc/filesystems", O_RDONLY)     = 3
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
file1.txt  file2.txt
+++ exited with 0 +++

If you want to display files opened by a specific process like SSH, run the following command:

strace -f -e open /usr/sbin/sshd 2>&1 | grep ssh
Output
open("/etc/ssh/sshd_config", O_RDONLY)  = 3
open("/etc/ssh/ssh_host_rsa_key", O_RDONLY) = -1 EACCES (Permission denied)
open("/etc/ssh/ssh_host_rsa_key", O_RDONLY) = -1 EACCES (Permission denied)
open("/etc/ssh/ssh_host_ecdsa_key.pub", O_RDONLY) = 3
Could not load host key: /etc/ssh/ssh_host_ecdsa_key
open("/etc/ssh/ssh_host_ed25519_key.pub", O_RDONLY) = 3
Could not load host key: /etc/ssh/ssh_host_ed25519_key

To trace network-related system calls, run the following command:

strace -e network nc -v -n 127.0.0.1 80
Output
socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
Connection to 127.0.0.1 80 port [tcp/*] succeeded!

3. Attach to Already Running Process

If a process is already running, you can trace it using its PID as shown below:

strace -p 5315
Output
Process 5315 attached
restart_syscall(<... resuming interrupted call ...>) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ffdc25fd048, FUTEX_WAKE_PRIVATE, 1) = 0
lseek(31, 0, SEEK_SET)                  = 0
read(31, "1185755 22902 18214 39954 0 1079"..., 4095) = 38
lseek(32, 0, SEEK_SET)                  = 0
read(32, "Name:tchromenState:tR (running)n"..., 4095) = 1020
futex(0x7ffdc25fd074, FUTEX_WAIT_BITSET_PRIVATE, 1, {3799, 9175}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ffdc25fd048, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7ffdc25fd074, FUTEX_WAIT_BITSET_PRIVATE, 1, {3802, 10202}, ffffffff^CProcess 5315 detached

This command will continuously showing system calls made by the process. You can press CTRL+C to stop it.

where:

5315 is a process ID of the running process.

4. Redirect Trace Output to a File

You can use -o flag with strace command to save the strace output to specified file.

strace -o file_out.txt ls file1.txt

You can now display the content of the file file_out.txt with the following command:

cat file_out.txt

5. Print Time Spent on System Calls

To print the relative timestamp of each call, use the -r flag as shown below.

strace -r ls file1.txt
Output
     0.000000 execve("/bin/ls", ["ls", "file1.txt"], [/* 61 vars */]) = 0
     0.000947 brk(0)                    = 0xaf3000
     0.000450 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
     0.000706 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f01b1ccb000
     0.000319 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
     0.000093 close(1)                  = 0
     0.000069 munmap(0x7f01b1cca000, 4096) = 0
     0.000078 close(2)                  = 0
     0.000104 exit_group(0)             = ?
     0.000184 +++ exited with 0 +++

To display the time difference between the starting and the end of each system call made by ls command, use the -T option.

strace -T ls file1.txt
Output
execve("/bin/ls", ["ls", "file1.txt"], [/* 61 vars */]) = 0 <0.000908>
brk(0)                                  = 0x1d72000 <0.000050>
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory) <0.000066>
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc895610000 <0.000059>
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory) <0.000060>
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000072>
fstat(3, {st_mode=S_IFREG|0644, st_size=114633, ...}) = 0 <0.000052>
mmap(NULL, 114633, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fc8955f4000 <0.000062>
close(3)                                = 0 <0.000050>
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory) <0.000059>
open("/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3 <0.000068>
read(3, "177ELF2113>1["..., 832) = 832 <0.000057>
fstat(3, {st_mode=S_IFREG|0644, st_size=134296, ...}) = 0 <0.000052>
mmap(NULL, 2238192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fc8951cd000 <0.000064>
mprotect(0x7fc8951ed000, 2093056, PROT_NONE) = 0 <0.000085>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc89560f000 <0.000026>
write(1, "file1.txtn", 10file1.txt
)             = 10 <0.000029>
close(1)                                = 0 <0.000021>
munmap(0x7fc89560f000, 4096)            = 0 <0.000029>
close(2)                                = 0 <0.000022>
exit_group(0)                           = ?
+++ exited with 0 +++

To print the wall clock time of each system call, run the following command:

strace -t ls file1.txt
Output
10:58:25 execve("/bin/ls", ["ls", "file1.txt"], [/* 61 vars */]) = 0
10:58:25 brk(0)                         = 0xc30000
10:58:25 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
10:58:25 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd4db396000
10:58:25 write(1, "file1.txtn", 10file1.txt
)    = 10
10:58:25 close(1)                       = 0
10:58:25 exit_group(0)                  = ?
10:58:25 +++ exited with 0 +++

The -tt option displays timestamp followed by microsecond.

strace -tt ls file1.txt

6. Display Instruction Pointer of System Call

You can use -i flag with strace command to print the instruction pointer at the time of each system call made by the command:

strace -i ls file1.txt
Output
[00007efd8cfeb337] execve("/bin/ls", ["ls", "file1.txt"], [/* 61 vars */]) = 0
[00007f5ab611e18c] brk(0)               = 0x239e000
[00007f5ab611f537] access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
[00007f5ab611f65a] mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5ab6326000
[00007f5ab5a01870] write(1, "file1.txtn", 10file1.txt
) = 10
[00007f5ab5a01f60] close(1)             = 0
[00007f5ab5a0a9f7] munmap(0x7f5ab6325000, 4096) = 0
[00007f5ab5a01f60] close(2)             = 0
[00007f5ab59d7309] exit_group(0)        = ?
[????????????????] +++ exited with 0 +++

7. Generate a System Call Report

You can use the -c flag to get the useful statistical report for the execution trace.

strace -c ls /var/www/html
Output
index.html
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         8           read
  0.00    0.000000           0         1           write
  0.00    0.000000           0         9           open
  0.00    0.000000           0        12           close
  0.00    0.000000           0         1           stat
  0.00    0.000000           0        10           fstat
  0.00    0.000000           0        23           mmap
  0.00    0.000000           0        14           mprotect
  0.00    0.000000           0         3           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         2           ioctl
  0.00    0.000000           0         8         8 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         2           getdents
  0.00    0.000000           0         2         2 statfs
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           openat
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                   101        10 total

In the above output, the “calls” column indicated how many times that particular system call was executed.

8. Print Debugging Output of strace

To print debugging information for strace command, use -d flag as shown below:

strace -d ls file1.txt
Output
ptrace_setoptions = 0x11
new tcb for pid 6453, active tcbs:1
 [wait(0x80137f) = 6453] ?? (128),PTRACE_EVENT_?? (128)
pid 6453 has TCB_STARTUP, initializing it
setting opts 11 on pid 6453
 [wait(0x80057f) = 6453] ?? (128),PTRACE_EVENT_?? (128)
 [wait(0x127f) = 6453] WIFSTOPPED,sig=SIGCONT
 [wait(0x857f) = 6453] WIFSTOPPED,sig=133
execve("/bin/ls", ["ls", "file1.txt"], [/* 61 vars */] [wait(0x4057f) = 6453] WIFSTOPPED,sig=SIGTRAP,PTRACE_EVENT_EXEC
 [wait(0x857f) = 6453] WIFSTOPPED,sig=133
) = 0
 [wait(0x857f) = 6453] WIFSTOPPED,sig=133
brk(0 [wait(0x857f) = 6453] WIFSTOPPED,sig=133
)                                  = 0x25bc000
 [wait(0x857f) = 6453] WIFSTOPPED,sig=133
exit_group(0)                           = ?
 [wait(0x0000) = 6453] WIFEXITED,exitcode=0
+++ exited with 0 +++
dropped tcb for pid 6453, 0 remain

9. Trace System Calls Based on a Certain Condition

You can also trace the system calls based on the specific condition. For example, trace all the system calls related to memory management run the following command:

strace -q -e memory ls file1.txt
Output
brk(0)                                  = 0x248d000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f68e9ac4000
mmap(NULL, 114633, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f68e9aa8000
mmap(NULL, 2238192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f68e9681000
mprotect(0x7f68e96a1000, 2093056, PROT_NONE) = 0
mmap(0x7f68e98a0000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1f000) = 0x7f68e98a0000
mmap(0x7f68e98a2000, 5872, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f68e98a2000
mmap(NULL, 2126336, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f68e9479000
mmap(0x7f68e8e74000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f68e8e74000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f68e9aa6000
mmap(NULL, 2113760, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f68e8a6d000
mprotect(0x7f68e8a71000, 2093056, PROT_NONE) = 0
mmap(0x7f68e8c70000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f68e8c70000
brk(0)                                  = 0x248d000
brk(0x24ae000)                          = 0x24ae000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f68e9ac3000
munmap(0x7f68e9ac3000, 4096)            = 0
mmap(NULL, 7216688, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f68e838b000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f68e9ac3000
file1.txt
munmap(0x7f68e9ac3000, 4096)            = 0
+++ exited with 0 +++

To trace the signal realted system calls, run the following command:

strace -e signal ls file1.txt
Output
file1.txt
+++ exited with 0 +++

To trace the process realted system calls, run the following command:

strace -e process ls file1.txt
Output
execve("/bin/ls", ["ls", "file1.txt"], [/* 61 vars */]) = 0
arch_prctl(ARCH_SET_FS, 0x7fb8196a8840) = 0
file1.txt
exit_group(0)                           = ?
+++ exited with 0 +++

Conclusion

In the above guide, you learned how to use the strace command with several examples. This tool is very useful for system administrators and programmers to debug and troubleshoot any program.

Source link

- Advertisement -

More articles

LEAVE A REPLY

Please enter your comment!
Please enter your name here

Latest article