shell

Understanding the strace command

strace is a utility that traces system calls and signals. It is very useful for debugging purposes, specially if you don’t have the source code of the problematic software. In its simple form it works like this:

$ strace ls /tmp

strace ls /tmp/
execve("/bin/ls", ["ls", "/tmp/"], [/* 80 vars */]) = 0
brk(0)                                  = 0x1c3e000
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) = 0x7fece6d1e000
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=113156, ...}) = 0
mmap(NULL, 113156, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fece6d02000
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, "\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"..., 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) = 0x7fece68db000
mprotect(0x7fece68fb000, 2093056, PROT_NONE) = 0
mmap(0x7fece6afa000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1f000) = 0x7fece6afa000
mmap(0x7fece6afc000, 5872, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fece6afc000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libacl.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\0`\34\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=31168, ...}) = 0
mmap(NULL, 2126336, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fece66d3000
mprotect(0x7fece66da000, 2093056, PROT_NONE) = 0
mmap(0x7fece68d9000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7fece68d9000
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\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320\37\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1840928, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fece6d01000
mmap(NULL, 3949248, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fece630e000
mprotect(0x7fece64c9000, 2093056, PROT_NONE) = 0
mmap(0x7fece66c8000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1ba000) = 0x7fece66c8000
mmap(0x7fece66ce000, 17088, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fece66ce000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libpcre.so.3", 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\260\27\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=252032, ...}) = 0
mmap(NULL, 2347200, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fece60d0000
mprotect(0x7fece610d000, 2093056, PROT_NONE) = 0
mmap(0x7fece630c000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3c000) = 0x7fece630c000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libdl.so.2", 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\320\16\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=14664, ...}) = 0
mmap(NULL, 2109744, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fece5ecc000
mprotect(0x7fece5ecf000, 2093056, PROT_NONE) = 0
mmap(0x7fece60ce000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7fece60ce000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libattr.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\0\300\20\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=18624, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fece6d00000
mmap(NULL, 2113760, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fece5cc7000
mprotect(0x7fece5ccb000, 2093056, PROT_NONE) = 0
mmap(0x7fece5eca000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7fece5eca000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fece6cff000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fece6cfd000
arch_prctl(ARCH_SET_FS, 0x7fece6cfd840) = 0
mprotect(0x7fece66c8000, 16384, PROT_READ) = 0
mprotect(0x7fece5eca000, 4096, PROT_READ) = 0
mprotect(0x7fece60ce000, 4096, PROT_READ) = 0
mprotect(0x7fece630c000, 4096, PROT_READ) = 0
mprotect(0x7fece68d9000, 4096, PROT_READ) = 0
mprotect(0x7fece6afa000, 4096, PROT_READ) = 0
mprotect(0x619000, 4096, PROT_READ)     = 0
mprotect(0x7fece6d20000, 4096, PROT_READ) = 0
munmap(0x7fece6d02000, 113156)          = 0
statfs("/sys/fs/selinux", 0x7fff9619bf30) = -1 ENOENT (No such file or directory)
statfs("/selinux", 0x7fff9619bf30)      = -1 ENOENT (No such file or directory)
brk(0)                                  = 0x1c3e000
brk(0x1c5f000)                          = 0x1c5f000
open("/proc/filesystems", O_RDONLY)     = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fece6d1d000
read(3, "nodev\tsysfs\nnodev\trootfs\nnodev\tr"..., 1024) = 388
read(3, "", 1024)                       = 0
close(3)                                = 0
munmap(0x7fece6d1d000, 4096)            = 0
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=7216688, ...}) = 0
mmap(NULL, 7216688, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fece55e5000
close(3)                                = 0
ioctl(1, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(1, TIOCGWINSZ, {ws_row=56, ws_col=205, ws_xpixel=0, ws_ypixel=0}) = 0
stat("/tmp/", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=12288, ...}) = 0
openat(AT_FDCWD, "/tmp/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3
getdents(3, /* 24 entries */, 32768)    = 872
getdents(3, /* 0 entries */, 32768)     = 0
close(3)                                = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 16), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fece6d1d000
write(1, "config-err-j77Qvd  cscope.13617 "..., 179config-err-j77Qvd  cscope.13617  cscope.25631  hsperfdata_fapesteguia  hsperfdata_root    mozilla_fapesteguia0  plugtmp  ssh-rmoRE0wRzPrI  tmp76zsn8nm  unity_support_test.0  vlJwr9R
     ) = 179
close(1)                                = 0
munmap(0x7fece6d1d000, 4096)            = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

As you can see, all the system calls performed by the executable are traced and shown in the screen. This is interesting since you can see that a simple ls invocation does much more things than meet the eye. For example, we can see that the argument for ls (the /tmp directory) is opened using openat and not a simple open:

openat(AT_FDCWD, "/tmp/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3

Since the output can be overwhelming and easily fill the whole buffer of our terminal, we can use the -o flag to redirect the output to a file. For example:

$ strace -o output ls /tmp/

A nice way to obtain an overview of the system calls used by an applications is using the -c flag (command output omitted):

$strace -c ls /tmp/

% 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 this particular invocation of ls, the most used syscall is mmap (mapping files and/or allocating memory).

Let’s see what happens when we change the command to do a recursive listing of the whole disk (the output has been omitted again for clarity purposes)

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
56.91    0.104196           0    309724       103 getdents
27.43    0.050228           0    532887           write
12.57    0.023007           0    156144      1276 openat
1.75    0.003197           0    154882           close
1.33    0.002431           0    154881           fstat
0.01    0.000016           1        12           brk
0.01    0.000015           8         2         2 statfs
0.00    0.000000           0        10           read
0.00    0.000000           0        19         7 open
0.00    0.000000           0         1           stat
0.00    0.000000           0        28           mmap
0.00    0.000000           0        14           mprotect
0.00    0.000000           0         4           munmap
0.00    0.000000           0         2           ioctl
0.00    0.000000           0         8         8 access
0.00    0.000000           0         4           mremap
0.00    0.000000           0         1           execve
0.00    0.000000           0         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.183090               1308624      1396 total

That is a very different output! Most of the time is now spent on the getdents syscall (to get directory entries) and write takes more than 25% percent of the time (mostly to write the output).

strace provides very convenient flags. For example, if we are interested in a particular syscall, we can do something like this (output omitted again):

$ strace -e trace=openat ls /tmp/
openat(AT_FDCWD, "/tmp/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 3

+++ exited with 0 +++

strace is an essential Linux tool for both sysadmins and developers since it helps to diagnose a big variety of problems. I suggest you check the manual and practice to get comfortable with it.

It is also interesting to note that strace shows information about system calls. Those functions must not be mistaken with the standard C library functions. Syscalls are one of the kernel interfaces available to user processes. For example, since malloc is not a syscall but a standard C library function you will not see those calls in strace’s output.

Enjoy!

speak up

Add your comment below, or trackback from your own site.

Subscribe to these comments.

Be nice. Keep it clean. Stay on topic. No spam.

You can use these tags: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>

*Required Fields