Debugging with strace
Dig Deep
After "Hello World," you really need to look at system calls in more detail. In this second of two articles, we'll
look at debugging in the real world.
By Juliet Kemp
Stephen Mcsweeny, 123RF
An article in the June issue [1] explored the very useful system call tracer strace [2]. Strace helps you hunt
down the source of problems with home-grown apps or buggy open source programs that won't quite work on
your system. In this article, I take a closer look at how to interpret some of the system call information
discovered through strace and describe some ways to make strace more useful in practical situations.
Hello Again!
In the previous article, I introduced the simple test program shown in Listing 1. To run strace on this program
and send the output to a file, I typed:
strace -o outputfile.txt helloworld.c
The strace output for Listing 1 is shown in Listing 2. A close look at a couple of lines in the output will give
you some insights into how Linux deals with files and memory.
Listing 1: helloworld.c
01 #include
02
03 main()
04 {
05 printf("Hello World");
06 }
Listing 2: Complete strace for helloworld.c
01 execve("./helloworld", ["./helloworld"], [/* 20 vars */]) = 0
02 uname({sys="Linux", node="the.earth.li", ...}) = 0
03 brk(0) = 0x501000
04 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
05 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2afb0be09000
06 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
07 open("/etc/ld.so.cache", O_RDONLY) = 3
08 fstat(3, {st_mode=S_IFREG|0644, st_size=43270, ...}) = 0
09 mmap(NULL, 43270, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2afb0be0b000
10 close(3) = 0
Dig Deep 1
11 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
12 open("/lib/libc.so.6", O_RDONLY) = 3
13 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200\305"..., 640) = 640
14 lseek(3, 624, SEEK_SET) = 624
15 read(3, "\4\0\0\0\20\0\0\0\1\0\0\0GNU\0\0\0\0\0\2\0\0\0\6\0\0\0"..., 32) = 32
16 fstat(3, {st_mode=S_IFREG|0755, st_size=1286104, ...}) = 0
17 mmap(NULL, 2344904, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x2afb0bf0a000
18 mprotect(0x2afb0c02b000, 1161160, PROT_NONE) = 0
19 mmap(0x2afb0c12b000, 98304, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x
20 mmap(0x2afb0c143000, 14280, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0
21 close(3) = 0
22 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2afb0c147000
23 mprotect(0x2afb0c12b000, 86016, PROT_READ) = 0
24 arch_prctl(ARCH_SET_FS, 0x2afb0c1476d0) = 0
25 munmap(0x2afb0be0b000, 43270) = 0
26 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 51), ...}) = 0
27 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2afb0be0b000
28 write(1, "Hello World", 11) = 11
29 munmap(0x2afb0be0b000, 4096) = 0
30 exit_group(11) = ?
/etc/ld.so.nohwcap
In Listing 2, notice that the program tries to access /etc/ld.so.nohwcap without success. For instance, line 11
provides the message:
access flfl
("/etc/ld.so.nohwcap", F_OK) flfl
= -1 ENOENT flfl
(No such file or directory)
In this case, the problem is pretty hard to track down because /etc/ld.so.nohwcap is an under-documented file.
This step reveals what sorts of libraries the linker looks for.
If /etc/ld.so.nohwcap is present, the linker loads the non-optimized version of a library (i.e., not optimized for
your particular hardware). If it's not present, the linker will go looking for the hardware-optimized version.
For more information on ld.so, you can check out the man page, but basically it's responsible for loading all
shared libraries, preparing a program to run, and running it. Any Linux program will need ld.so to do its thing
before it can run, unless it has been linked statically.
Sandboxes and Pointers
One of the great things about Linux is how well documented the system calls are. From the man pages, you
can get information on any of the functions you see in strace output with man functionname or man 2
functionname. The documentation makes it easy to learn a lot just by looking at strace output.
User programs on a modern system run in a little sandbox: They're not permitted to interact directly with the
computer (so you can't just shove numbers into registers to make things happen, as you could 20 years ago).
Instead, everything goes through the kernel, and strace traces these messages to the kernel. If you don't see
any strace output for a bit, it doesn't necessarily mean that your program is stuck; it might be doing stuff
within its own sandbox (e.g., calculations) that doesn't require it to talk to the kernel.
System calls often use pointers to data structures. A pointer is a memory reference that tells the system where
to look in memory to find a particular piece of information. If you were a computer, this would be great, but
it's not so good when you're a human, because digging around in memory isn't easy. When strace sees a
pointer, instead of giving you the value of the pointer, it does the lookup for you and returns the contents of
that pointer so that you're shown the actual data. When you're reading man pages and it talks about a pointer
to a data structure or a pointer to a buffer, remember that what you see in the strace output is the contents of
that data structure.
Dig Deep 2
Files and Memory
As you might have noticed when first looking at the output for this program, one of the lines that comes up
quite frequently is mmap. The mmap call is responsible for mapping files or devices into memory. Look at
how an mmap call is structured in Listing 3, for example.
Listing 3: mmap Call
01 open("/etc/ld.so.cache", O_RDONLY) = 3
02 fstat(3, {st_mode=S_IFREG|0644, st_size=43270, ...}) = 0
03 mmap(NULL, 43270, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2afb0be0b000
Before the mmap call, the output shows that the /etc/ld.so.cache file has opened successfully with a file
descriptor of 3.
Then there's a call to fstat. The first argument, 3, is the file descriptor for the file opened in the previous line.
Perhaps you've noticed that when files are opened to a number, the numbers start at 3. This occurs because the
file descriptors 0-2 are already allocated: 0 to stdin, 1 to stdout, and 2 to stderr.
The fstat call returns information about a file. The first argument is the file descriptor, which, as here, will
have been set up by an earlier open call. The next section in the brackets is a stat structure. Strace doesn't
actually show all of it (hence the ... at the end), but the stat structure contains information about the file: user
and group ID of owner, device ID, time last modified, and so on. (If you want to get full information on these
sorts of structures, you can use the strace option -v.)
From the stat structure, you can see the file protection and size (in bytes) of the file. You should be able to
interpret both of these values: The protection uses the same coding as chmod, so here, that's owner+group
read, owner write, and owner execute (0644), and the size is just a number. (The other part of the mode field is
a flag identifying whether it's a regular file, directory, or something else: S_IFREG means it's a regular file.)
The fstat call returns 0 for success, as here: When called, the function fills in the stat structure that is recorded
here.
In the mmap call, the first argument is a memory location, intended as a hint to the system as to where the
memory mapping might start. Usually, as in this case, it's zero (NULL, i.e., the system has free rein to use any
location it likes). The next number, which you might recognize, is the size in bytes of the file (so here, 43270
matches the size in the stat structure in the fstat call). The PROT* section specifies the protection that this
memory should have, and it can't conflict with the mode of the file. Here, I'm opening with READ only.
Because I'm not running as root, I don't have write or execute access to this file.
Next, the mmap call maps data from a file into memory, and these options specify how that mapping works.
Here, MAP_PRIVATE means that any changes made to the mapped region (i.e., any changes made to
memory) aren't shared with any other processes and aren't written back to the original file, which obviously is
a good idea in the case of a system file like ld.so.cache! The next argument is, yet again, 3, the file descriptor.
The final value is the offset, which here is set to 0.
The value returned by mmap is the memory address at which the mapping starts. To see when the system
cleans up after itself, look for a munmap call later on with that memory address - that will clear out the
memory address.
Note that you will get this call in a C trace, but not in a Perl trace. Because C explicitly sets up its own
memory, it also explicitly clears up after itself (or it can, depending on the details of the implementation of
malloc). Perl, on the other hand, just leaves this to be done by the system in due course.
While I'm looking at system calls in detail, what about the exit_group call that ends both strace outputs? All
this does is exit threads. Unlike exit, it clears up not only that thread, but all threads in the current group.
Static or Dynamic
Dig Deep 3
Static linking means that a program brings its own libraries. Dynamic linking means that a program uses the
system libraries. With dynamic linking, you only have to have one copy of all the standard system libraries,
rather than a copy per program. Pretty much all Linux programs use dynamic linking now, unless they've
been specifically optimized to reduce overhead.
Options
So far, I've used strace with very few options: just -o to send the output to a file. But a variety of options are
available that make it easier to understand and debug programs.
If you want to use strace with any complicated programs, you'll probably want to be able to trace their forks as
well. The -f switch traces child processes (forks) as they are created. -F will do the same thing, but with
vforks. (vfork is a special case of fork that doesn't take certain sorts of information from the parent process.)
Another useful set of options have to do with time. These can come in handy if you're debugging a program
that hangs or that seems to be running particularly slowly. In this way, you can find out where the problem
actually lies. The -t, -tt, and -ttt switches all put the time of day - to the second, microsecond, or
second+microsecond, written as seconds since epoch - at the start of each line. The -T switch shows the time
spent in system calls - that is, the time difference between the beginning and end of each system call.
Similarly, -r prints a relative time stamp at the start of each system call.
The -c switch counts the time, calls, and errors for each system call and summarizes this information when the
program exits. This information is helpful if you're debugging and you're not sure where to start, because it
will help you work out where the problem might lie.
Additionally, you can use -e trace=set to trace only the system calls you specify - for example, -e
trace=open,read,write (note the lack of spaces) to trace only the open, read, and write system calls. This can
minimize the amount of output you have to wade through if you've used -c to identify what you think are the
problem calls.
Finally, if you want more gory details for your traces, try -v, which gives full values of stat, environment, and
other common calls. (Use the -v flag and then have another look at the fstat call as discussed above to get all
the information that's returned about that file.)
Shell Script Wrappers
Although it's not always possible to run your command under "real" conditions when something goes wrong,
a possible workaround might be to write a shell script wrapper for the command so that you can run it via
strace.
Move your program command out of the way by renaming it to, for example, command.old. Then save the
script in Listing 4 to command.
Listing 4: Wrapping Another Command with strace
01 #!/bin/sh
02 #
03 strace -o/tmp/command_out.$$ /usr/bin/command.old $*
This not only calls the real command program with any arguments you used but also runs strace on it and
dumps the output to a new file each time the script is called. Then you can check out what's happening under
these real circumstances. Don't forget to move the real program back where it belongs once you're done!
Another very useful option is to use the -p PID option: This attaches strace to the process with the specified
process ID. So if you suddenly see a process hanging or eating up lots of CPU, you can find out what it's
doing in real time.
Dig Deep 4
Conclusion
Knowing what system calls should look like and how they work makes it much easier to notice when
something's not quite right. Often it's clear very quickly what's going wrong (e.g., a failed open call to a
particular file). Looking at file permissions can also be helpful.
Strace is incredibly useful when debugging, but it can also be educational to run it on programs or commands
that are running perfectly well, just to see what's going on under the hood of your working system.
One of the major advantages of running Linux is that the innards of the system are both accessible and
(largely) well documented. Strace is one of the tools that can let you make the most of this access.
INFO
[1] strace article part 1: http://www.linuxpromagazine.com/issues/2009/103/bug_bumper
[2] strace tool: http://sourceforge.net/projects/strace/
THE AUTHOR
Juliet Kemp has been playing around with Linux ever since she found out that it was more fun than Finals
revision, and has been a sys admin for about five years. She finds strace output deeply fascinating, and had
great fun delving into system call man pages while researching this article.
Dig Deep 5