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.

By  

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
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
 -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
mmap2(0x28b000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|
MAP_DENYWRITE, 3, 0x156) = 0x28b000
mmap2(0x28e000, 9668, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|
MAP_ANONYMOUS, -1, 0) = 0x28e000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
 -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
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
 -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
/home/shs

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
/u/faculty/shs
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
/u/faculty/shs
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
/u/faculty/shs
     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.

Photo Credit: 

flickr / Bekathwia

Join us:
Facebook

Twitter

Pinterest

Tumblr

LinkedIn

Google+

Operating SystemsWhite Papers & Webcasts

See more White Papers | Webcasts

Answers - Powered by ITworld

Ask a Question
randomness