The strace command is useful for debugging any command or a script. Thachievedheived by using a concept called command on command. The strace command has some other sister commands like ps, pstree, lsof etc.

What is Linux strace command do?

The primary purpose of the strace command is to show system calls which are created by the kernel when working with some process. Say suppose you write a program and want to see how it interacts with the system when it is executed, strace is your friend. The strace command is just a light debugger for your programs and command. In below example, we tried to run the pwd command and showed you what steps will be taken place.

Syntax of strace command

strace <command>

Example:

root@linuxnix:~# strace pwd
execve("/bin/pwd", ["pwd"], [/* 73 vars */]) = 0
brk(NULL) = 0x148c000
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) = 0x7f5f89746000
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=162567, ...}) = 0
mmap(NULL, 162567, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5f8971e000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\t\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1868984, ...}) = 0
mmap(NULL, 3971488, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f5f89159000
mprotect(0x7f5f89319000, 2097152, PROT_NONE) = 0
mmap(0x7f5f89519000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c0000) = 0x7f5f89519000
mmap(0x7f5f8951f000, 14752, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f5f8951f000
close(3) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5f8971d000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5f8971c000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5f8971b000
arch_prctl(ARCH_SET_FS, 0x7f5f8971c700) = 0
mprotect(0x7f5f89519000, 16384, PROT_READ) = 0
mprotect(0x606000, 4096, PROT_READ) = 0
mprotect(0x7f5f89748000, 4096, PROT_READ) = 0
munmap(0x7f5f8971e000, 162567) = 0
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=2981280, ...}) = 0
mmap(NULL, 2981280, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5f88e81000
close(3) = 0
brk(NULL) = 0x148c000
brk(0x14ad000) = 0x14ad000
getcwd("/root", 4096) = 6
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 5), ...}) = 0
write(1, "/root\n", 6/root
) = 6
close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++

Let me try to explain what just happened:

Step A: It shows kernel is searched for the pwd command in PATH variable and execute that.

execve("/bin/pwd", ["pwd"], [/* 73 vars */]) = 0

Step B: Kernel checks if the user has access to read this file or not.

Step C: Access required library files for executing this command.

access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)

…………………………..

Step X: Gets current working directory.

getcwd("/home/surendra/code/sh", 4096) = 23

 

Step Y: Writes the current directory output to a file descriptor.

Output:

write(1, "/root\n", 6/root

Step Z: Closes and exit the command execution

close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++

I skipped many steps between Step C and Step X intentionally to show many steps are involved. And it is out of this post scope to explain each thing.

So the primary purpose of the strace command is to trace Kernel calls and see if there is an issue within your command or shell script execution.

Below are some frequently used command line options when using Strace command.

Simple strace for a command

Just execute the pwd command and see what happens.

Example:

surendra@linuxnix:~/code/sh$ strace pwd
execve("/bin/pwd", ["pwd"], [/* 68 vars */]) = 0
brk(NULL) = 0x735000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
..........
brk(0x756000) = 0x756000
getcwd("/home/surendra/code/sh", 4096) = 23
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 5), ...}) = 0
write(1, "/home/surendra/code/sh\n", 23/home/surendra/code/sh
) = 23
close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++

Trace a particular system call with strace

The strace command can be used to filter out particular system call without the help of grep. Use -e to specify which system call you want to see.

strace -e <call-type> <command>

Example Output:

surendra@linuxnix:~/code/sh$ strace -e open pwd
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
/home/surendra/code/sh
+++ exited with 0 +++

Some of the frequently used system call options are

execve, access, open, read, and write

fstat, getrlimit, getdents, ioctl and statfs.

close and brk

mmap and mprotect

Trace multiple systems calls for a command

We can trace multiple system calls instead of one as shown below.

strace -e trace=open, write <command>

Example:

surendra@linuxnix:~/code/sh$ strace -e trace=open,write pwd
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
write(1, "/home/surendra/code/sh\n", 23/home/surendra/code/sh
) = 23
+++ exited with 0 +++

Trace network calls.

One of the system call option available is a network; We can use this to see if any network calls are happening or not.

Example:

root@linuxnix:/home/surendra# strace -e trace=network ifconfig
socket(PF_LOCAL, SOCK_DGRAM, 0) = 3
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
socket(PF_INET6, SOCK_DGRAM, IPPROTO_IP) = 5
docker0 Link encap:Ethernet HWaddr 02:42:5a:71:90:c8
inet addr:172.17.0.1 Bcast:0.0.0.0 Mask:255.255.0.0
UP BROADCAST MULTICAST MTU:1500 Metric:1
RX packets:0 errors:0 dropped:0 overruns:0 frame:0
TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:0
RX bytes:0 (0.0 B) TX bytes:0 (0.0 B)

Trace a PID of process.

strace -p <pid>

Example(clipped):

recvmsg(5, 0x7ffede033080, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvmsg(12, 0x7ffede0333b0, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvmsg(20, 0x7ffede0333b0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}, {fd=9, events=POLLIN|POLLPRI}, {fd=12, events=POLLIN}, {fd=14, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 7, 0) = 0 (Timeout)
recvmsg(5, {msg_name(0)=NULL, msg_iov(1)=[{"\34\0*\331\n\0\240\4\\\1\0\0\247\274F\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 4096}], msg_controllen=0, msg_flags=0}, 0) = 32
recvmsg(5, 0x7ffede033270, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvmsg(5, 0x7ffede033270, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvmsg(5, 0x7ffede033270, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvmsg(5, 0x7ffede033270, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvmsg(5, 0x7ffede0333b0, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvmsg(12, 0x7ffede0333b0, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvmsg(20, 0x7ffede0333b0, 0) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}, {fd=9, events=POLLIN|POLLPRI}, {fd=12, events=POLLIN}, {fd=14, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}], 7, 14

List all calls and time for a command

strace -c <command>

Example:

root@linuxnix:/home/surendra# strace -c pwd
/home/surendra
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
0.00 0.000000 0 1 read
0.00 0.000000 0 1 write
0.00 0.000000 0 3 open
0.00 0.000000 0 5 close
0.00 0.000000 0 4 fstat
0.00 0.000000 0 9 mmap
0.00 0.000000 0 4 mprotect
0.00 0.000000 0 1 munmap
0.00 0.000000 0 3 brk
0.00 0.000000 0 3 3 access
0.00 0.000000 0 1 execve
0.00 0.000000 0 1 getcwd
0.00 0.000000 0 1 arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00 0.000000 37 3 total

Trace a process with time stamp

For relative time stamp

strace -r <command>

Example(Clipped):

root@linuxnix:/home/surendra# strace -r pwd
0.000000 execve("/bin/pwd", ["pwd"], [/* 72 vars */]) = 0
0.000207 brk(NULL) = 0x164a000
0.000034 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
0.000028 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1775103000
0.000028 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
0.000022 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
0.000022 fstat(3, {st_mode=S_IFREG|0644, st_size=162567, ...}) = 0
0.000022 mmap(NULL, 162567, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f17750db000
0.000019 close(3) = 0
0.000019 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
0.000023 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
0.000020 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\t\2\0\0\0\0\0"..., 832) = 832
0.000040 fstat(3, {st_mode=S_IFREG|0755, st_size=1868984, ...}) = 0

For prefixing time of the day

strace -t <command>

Example(Clipped output):

root@linuxnix:/home/surendra# strace -t pwd
06:55:40 execve("/bin/pwd", ["pwd"], [/* 72 vars */]) = 0
06:55:40 brk(NULL) = 0x2213000
06:55:40 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
06:55:40 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2fa248c000
06:55:40 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
06:55:40 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
06:55:40 fstat(3, {st_mode=S_IFREG|0644, st_size=162567, ...}) = 0
06:55:40 mmap(NULL, 162567, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f2fa2464000
06:55:40 close(3) = 0
06:55:40 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
06:55:40 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3

For prefixing time with microseconds

strace -tt <command>

Example:

root@linuxnix:/home/surendra# strace -tt pwd
06:56:40.430679 execve("/bin/pwd", ["pwd"], [/* 72 vars */]) = 0
06:56:40.430916 brk(NULL) = 0x1890000
06:56:40.430984 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
06:56:40.431046 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4335261000
06:56:40.431080 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
06:56:40.431106 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
06:56:40.431129 fstat(3, {st_mode=S_IFREG|0644, st_size=162567, ...}) = 0
06:56:40.431155 mmap(NULL, 162567, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f4335239000

For  Epoch time as well as microseconds

strace -ttt <command>

Example:

root@linuxnix:/home/surendra# strace -ttt pwd
1505768216.612804 execve("/bin/pwd", ["pwd"], [/* 72 vars */]) = 0
1505768216.613087 brk(NULL) = 0x21a7000
1505768216.613135 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
1505768216.613172 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd88413d000
1505768216.613202 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
1505768216.613223 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
1505768216.613246 fstat(3, {st_mode=S_IFREG|0644, st_size=162567, ...}) = 0
1505768216.613268 mmap(NULL, 162567, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fd884115000
1505768216.613287 close(3) = 0

Save traced command output to a file

strace -o <file_to_save> <command>

Example:

root@linuxnix:/home/surendra# strace -o pwd.txt pwd
/home/surendra

In our next post, we will see ltrace and mtrace commands.

Post Views: 26,946
The following two tabs change content below.
My Twitter profileMy Facebook profileMy Google+ profileMy YouTube channel

Surendra Anne

Mr Surendra Anne is from Vijayawada, Andhra Pradesh, India. He is a Linux/Open source supporter who believes in Hard work, A down to earth person, Likes to share knowledge with others, Loves dogs, Likes photography. He works as Devops Engineer with Taggle systems, an IOT automatic water metering company, Sydney . You can contact him at surendra (@) linuxnix dot com.