Unix: Having your way with strace

Ever need to look into a Unix process to see exactly what it's doing? The ps and top commands only give you a bird's eye view of what's going on. But strace will let you peer into a process' inner workings.

The strace utility is a lightweight debugger. It allows you to look at what a Unix process is doing step by step, whether it is opening files, invoking system calls or writing output to your screen. A process which appears to be hung might, in fact, be incredibly busy, but you might not know it unless you use a tool which is able to tell you what is happening step by step. The strace command lets you see what a process is doing, how it is interacting with the operating system. It monitors system calls and signals. As others have pointed out, using strace's output can be like drinking from a fire hose. You're likely to get a LOT of output and it's going to come shooting at you -- especially if your process is busy. If you're going to make good use of strace, it's good to have a basic understanding of what a system call is and some of the calls that you're likely to see. To gain some familiarity, you can use strace to look at a simple process or start a process and then watch everything it does. Here's an extremely simple example:

$ strace echo hello
execve("/bin/echo", ["echo", "hello"], [/* 28 vars */]) = 0
brk(0)                                  = 0x8f58000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=60257, ...}) = 0
mmap2(NULL, 60257, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7f94000
close(3)                                = 0
open("/lib/libc.so.6", O_RDONLY)        = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0\240\24\0004\0\0\0"...
, 512) = 512
 -1, 0) = 0xb7f93000
fstat64(3, {st_mode=S_IFREG|0755, st_size=1706232, ...}) = 0
mmap2(0x134000, 1426884, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENY
WRITE, 3, 0) = 0x134000
MAP_DENYWRITE, 3, 0x156) = 0x28b000
MAP_ANONYMOUS, -1, 0) = 0x28e000
close(3)                                = 0
 -1, 0) = 0xb7f92000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb7f926c0, limit:1048575, 
seg_32bit:1, contents:0, read_exec_only:0, 

limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0x28b000, 8192, PROT_READ)     = 0
mprotect(0x130000, 4096, PROT_READ)     = 0
munmap(0xb7f94000, 60257)               = 0
brk(0)                                  = 0x8f58000
brk(0x8f79000)                          = 0x8f79000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=56438560, ...}) = 0
mmap2(NULL, 2097152, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7d92000
close(3)                                = 0
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 5), ...}) = 0
 -1, 0) = 0xb7fa2000
write(1, "hello\n", 6hello
)                  = 6
close(1)                                = 0
munmap(0xb7fa2000, 4096)                = 0
exit_group(0)                           = ?

That's a lot of "goings on" for a command as simple as echo hello, but there's a lot of groundwork that must go on for even the most mundane Unix commands. The trace output shows numerous system calls, such as:

  • execve -- shell spawns a child process to handle the command entered
  • brk -- change data segment size
  • access -- check user's permissions
  • open command -- opening shared librarires
  • mmap2 calls -- mapping file (or data) into memory
  • mprotect -- control access to memory
  • munmap -- unmap files in memory
  • write -- a command that sends the "hello" output to your screen
  • close -- closing the file descriptor that represents standard output
  • fstat64 -- return information about a file
  • exit_group -- exit threads

If you prefer to see only select system calls (e.g., open), you can specify them by using the -e argument. In this command, we look only at open calls:

$ strace -e open pwd
open("/etc/ld.so.cache", O_RDONLY)      = 3
open("/lib/libc.so.6", O_RDONLY)        = 3
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3

You can look for more than one system call by turning your calls argument into a comma-separated list like this:

$ strace -e open,close pwd
open("/etc/ld.so.cache", O_RDONLY)      = 3
close(3)                                = 0
open("/lib/libc.so.6", O_RDONLY)        = 3
close(3)                                = 0
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
close(3)                                = 0
close(1)                                = 0

If you want to add a timestamp to your strace output so that you can see how long it takes to get from one step to the next, you can do so with the -t option:

$ strace -t -e open,close pwd
15:16:03 open("/etc/ld.so.cache", O_RDONLY) = 3
15:16:03 close(3)                       = 0
15:16:03 open("/lib/libc.so.6", O_RDONLY) = 3
15:16:03 close(3)                       = 0
15:16:03 open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
15:16:03 close(3)                       = 0
15:16:03 close(1)                       = 0

Or if you prefer your timestamp to be relative to the time the process started (rather than clock time), turn that -t option into a -r (for "relative") and you'll get just that:

$ strace -r -e open,close pwd
     0.000000 open("/etc/ld.so.cache", O_RDONLY) = 3
     0.000384 close(3)                  = 0
     0.000177 open("/lib/libc.so.6", O_RDONLY) = 3
     0.000409 close(3)                  = 0
     0.000698 open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
     0.000323 close(3)                  = 0
     0.000448 close(1)                  = 0

You can also use strace to examine a running process. Just use the -p argument along with the process ID.

$ strace -p 1234

If you would like to direct the output from strace to a file for later analysis, use the -o option and specify a file name.

$ strace -p 1234 -o 1234.out

The strace tool can be extremely handy when you want to view what a process is doing -- not just how much memory it's using or CPU it's consuming, but what it's doing step by step. I have found this tool (and other tracing tools) to be extremely useful when I needed to understand what a process was doing, not just how long it was running or whose account it was running under. After you've used strace for a while, the system calls and libraries will start to look familiar -- and you will probably find that what it can tell you about processes that seem to be having problems invaluable.

Read more of Sandra Henry-Stocker's Unix as a Second Language blog and follow the latest IT news at ITworld, Twitter and Facebook.

Join the Network World communities on Facebook and LinkedIn to comment on topics that are top of mind.

Copyright © 2013 IDG Communications, Inc.

IT Salary Survey: The results are in