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<stdio.h>
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
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, 0x121000) = 0x2afb0c12b000
20 mmap(0x2afb0c143000, 14280, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x2afb0c143000
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.

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

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.

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.