Introducing strace - a System call tracing and Signal reporting tool

By Amit Kumar Saha and Sayantini Ghosh

It's Cool to Know More Stuff

It is always fun to know how things actually work. All C programmers know that during the input-process-output cycle of their C codes, a number of System calls are invoked. Wouldn't be cool to to actually "see" what system calls are invoked by your program? This is the topic of interest here. Let's get started.

What is 'strace'?

'strace' is a tool which enables tracing the System calls made by a process during its execution. It also reports the signals (or software interrupts) that are recieved by the process.

According to the Linux manual page, in the simplest case 'strace runs the specified command until it exits. It intercepts and records the system calls which are called by a process and the signals which are received by a process. .

You can have a look at the various switches and options by typing in 'strace' on your terminal:

$ strace
usage: strace [-dffhiqrtttTvVxx] [-a column] [-e expr] ... [-o file]
              [-p pid] ... [-s strsize] [-u username] [-E var=val] ...
              [command [arg ...]]
   or: strace -c [-e expr] ... [-O overhead] [-S sortby] [-E var=val] ...
              [command [arg ...]]
-c -- count time, calls, and errors for each syscall and report summary

[[[etc.]]]

Tracing System calls

Let us start with a very simple demonstration of its working. Consider the following C code (Listing 1):

/* Listing 1*/

#include <stdio.h>

int main()
{
return 0;
}
          

Assume that the object file is 'temp.o'. Execute it with:

$strace ./temp.o

You will get the following trace:

execve("./temp.o", ["./temp.o"], [/* 36 vars */]) = 0
brk(0)                                  = 0x804a000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fba000
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=68539, ...}) = 0
mmap2(NULL, 68539, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7fa9000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/tls/i686/cmov/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`\1\000"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=1307104, ...}) = 0
mmap2(NULL, 1312164, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7e68000
mmap2(0xb7fa3000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13b) = 0xb7fa3000
mmap2(0xb7fa6000, 9636, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7fa6000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7e67000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb7e676c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb7fa3000, 4096, PROT_READ)   = 0
munmap(0xb7fa9000, 68539)               = 0
exit_group(0)                           = ?
Process 8909 detached

Let us now try to correlate our theoretical understanding with the 'trace' produced here.

As we know, when the user types in a command or a object file to be executed, the shell spawns a 'child' shell and and this child shell performs the execution. This is done with the System call 'execve'. Thus, the first line that we have in the trace is:

execve("./temp.o", ["./temp.o"], [/* 36 vars */]) = 0

This is followed by calls to 'brk()', 'open','access', 'open', 'close' and finally the process is detached from the shell which also exits using 'exit_group(0)'.

As is apparent, the trace shows all the system calls along with the arguments and the return value.

Signal reporting via strace

I shall now demonstrate the signal reporting capabilities of 'strace'. Consider the C- code (Listing 2):

/*Listing 2*/

#include <stdio.h>

int main()
{
int i;

for(i=0;i>=0;i++)
        printf("infinity\n");
return 0;
}

Assume, that the object file is 'temp-1.o'. Run it using:

$ strace -o trace.txt ./temp-1.o

NB: the '-o' switch will save the trace results to the file 'trace.txt'.

You will see that it shows you the 'write()' system call being called infintely. Now end the process using 'ctrl + c'

[[[...]]]

write(1, "ty\ninfinity\ninfinity\ninfinity\nin"..., 1024) = 1024
write(1, "nity\ninfinity\ninfinity\ninfinity\n"..., 1024) = 1024
write(1, "finity\ninfinity\ninfinity\ninfinit"..., 1024) = 1024
write(1, "infinity\ninfinity\ninfinity\ninfin"..., 1024) = 1024
write(1, "y\ninfinity\ninfinity\ninfinity\ninf"..., 1024) = 1024
write(1, "ity\ninfinity\ninfinity\ninfinity\ni"..., 1024) = 1024
write(1, "inity\ninfinity\ninfinity\ninfinity"..., 1024) = 1024
write(1, "nfinity\ninfinity\ninfinity\ninfini"..., 1024) = 1024
write(1, "\ninfinity\ninfinity\ninfinity\ninfi"..., 1024) = 1024
write(1, "ty\ninfinity\ninfinity\ninfinity\nin"..., 1024) = 1024
write(1, "nity\ninfinity\ninfinity\ninfinity\n"..., 1024) = 1024
write(1, "finity\ninfinity\ninfinity\ninfinit"..., 1024) = 1024
write(1, "infinity\ninfinity\ninfinity\ninfin"..., 1024) = 1024
write(1, "y\ninfinity\ninfinity\ninfinity\ninf"..., 1024) = 1024

[[[etc.]]]

Now, open the file 'trace.txt':

$cat trace.txt

The last couple of lines will be:

--- SIGINT (Interrupt) @ 0 (0) ---
+++ killed by SIGINT +++

Since we interrupted the process execution using 'ctrl + c', this caused the signal - SIGINT to be passed to the process and hence was reported by 'strace'.

Gathering statistics about the system calls

Using 'strace', it is also possible to gather some basic statistics regarding the system calls traced. This is achieved with the '-c' switch. For example:

$ strace -o trace-1.txt -c ./temp-1.o # run the above object code 'temp-1.o'
$ cat trace-1.txt 

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.007518           0     46702           write
  0.00    0.000000           0         1           read
  0.00    0.000000           0         2           open
  0.00    0.000000           0         2           close
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         3         3 access
  0.00    0.000000           0         1           brk
  0.00    0.000000           0         1           munmap
  0.00    0.000000           0         1           mprotect
  0.00    0.000000           0         7           mmap2
  0.00    0.000000           0         3           fstat64
  0.00    0.000000           0         1           set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00    0.007518                 46725         3 total

Among others, an useful piece of information that comes out from the above is that the process spends the maximum (100%) time calling 'write()' system call (called 46702) times.

End notes

This article provided a short introduction to some basic functionalities of 'strace'. This tool is most helpful in cases when you have only the binary of a bug-ridden, crash-prone program. Using this tool you can narrow down to the most likely cause of the crash.

Together with 'GNU Debugger' (gdb) and 'ltrace', 'strace' gives a lot of debugging powers to the Linux programmer.

Useful Links:

• Fun with strace and the GDB Debugger

Talkback: Discuss this article with The Answer Gang

Amit Kumar Saha

---

The author is a freelance technical writer. He mainly writes on the Linux kernel, Network Security and XML.

Sayantini Ghosh

---

The author is a 3rd year Computer Science & Engineering undergraduate from India. Her favorite subject is Operating Systems and is currently on a mission to successfully migrate to Linux from MS Windows/DOS where she often types "ls" instead of "dir".