Linux Processes and System Calls, Traced With strace

Originally published on Code Beneath.

Every program on Linux is a series of system calls. When you read a file, write to a socket, or spawn a child process, your code is asking the kernel to do the real work. The operating system intercepts these requests, checks permissions, manages resources, and returns results. A linux strace tutorial example shows you exactly where your program pauses, which syscalls it makes, and how long each one takes. This is not theoretical: strace is a production tool that lets you see the gap between what you think your code does and what it actually tells the kernel to do. Most developers skip this step and wonder why their program hangs, leaks file descriptors, or wastes syscalls on redundant operations.

This article walks through a real C program, runs strace on it, and maps each kernel request to what happens inside the kernel. You will see fork, execve, open, read, write, and close in action. You will understand why a single Python print statement can trigger dozens of syscalls. And you will learn to read strace output fast enough to debug a production issue in minutes, not hours.

What is strace and Why You Need It

strace is a system call tracer. It intercepts all syscalls made by a process and prints them to stderr. Each line shows the syscall name, arguments, and return value. strace works by ptrace, a Linux syscall that lets one process inspect and control another. The kernel pauses the traced process before and after each syscall, and strace reads the register state to extract argument and return values.

Why is this useful? Because it shows you the truth. Your code might think it is reading from a file, but strace shows you the actual sequence: open, fstat, mmap, read, close. If your program is slow, strace reveals whether it is spending time in user code or blocked in the kernel. If a program crashes mysteriously, strace shows the last few syscalls before death. If you are integrating low-level code, as we discuss in native language integration, strace is often the fastest way to see what went wrong.

A Minimal C Program to Trace

Let us start with a tiny program that does several things: open a file, read from it, write to stdout, fork a child, and execute a new program. This will show you the full life cycle of syscalls.

#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <fcntl.h>
#include <sys/wait.h>
#include <string.h>

int main() {
    // Open and read a file
    int fd = open("test.txt", O_RDONLY | O_CREAT, 0644);
    if (fd == -1) {
        perror("open");
        return 1;
    }

    // Write some content first
    int wfd = open("test.txt", O_WRONLY | O_TRUNC);
    write(wfd, "hello from test file\n", 21);
    close(wfd);

    // Read it back
    char buf[256];
    ssize_t n = read(fd, buf, sizeof(buf));
    if (n > 0) {
        write(STDOUT_FILENO, buf, n);
    }
    close(fd);

    // Fork and exec
    pid_t pid = fork();
    if (pid == 0) {
        // Child process
        execlp("echo", "echo", "child process output", NULL);
        perror("execlp");
        exit(1);
    } else if (pid > 0) {
        // Parent waits
        wait(NULL);
    } else {
        perror("fork");
        return 1;
    }

    return 0;
}

Compile this with gcc -o tracetest tracetest.c. Run it normally and you see some output. Now run it under strace and you see the machinery.

Running strace and Reading the Output

The simplest invocation is: strace ./tracetest

The output will be hundreds of lines. Here is what you get (truncated and annotated):

execve("./tracetest", ["./tracetest"], 0x7ffee55ad6e0 /* 54 vars */) = 0
brk(NULL)                               = 0x55a4c6a4d000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1234560000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap(NULL, 3449960, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f1234100000
mmap(0x7f12342a0000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x190000) = 0x7f12342a0000
mmap(0x7f12342a6000, 14440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f12342a6000
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1234556000
munmap(0x7f1234560000, 4096)            = 0
set_tid_address(0x7f12342a68c0)         = 24601
set_robust_list(0x7f12342a68d0, 24)    = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f12342a1f10, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 0) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8388608, rlim_max=RLIMIT_INFINITY}) = 0
open("test.txt", O_RDONLY|O_CREAT, 0644) = 3
open("test.txt", O_WRONLY|O_TRUNC, 0)  = 4
write(4, "hello from test file\n", 21) = 21
close(4)                                = 0
lseek(3, 0, SEEK_SET)                   = 0
read(3, "hello from test file\n", 256)  = 21
write(1, "hello from test file\n", 21)  = 21
close(3)                                = 0
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_USEREGS|CLONE_VM, child_tidptr=0x7f12342a68c0) = 24606
wait4(24606, NULL, 0, NULL)             = 24606
exit_group(0)                           = ?
+++ exited with code 0 +++

The first many lines are the loader and libc initialization. They happen before your main() runs. The interesting part is where your code actually works:

1. open("test.txt", O_RDONLY|O_CREAT, 0644) = 3: Opens the file for reading. The kernel returns file descriptor 3.

2. open("test.txt", O_WRONLY|O_TRUNC, 0) = 4: Opens the same file for writing and truncates it. fd 4.

3. write(4, "hello from test file\n", 21) = 21: Writes 21 bytes to fd 4. The kernel returns 21 (success).

4. close(4) = 0: Closes fd 4.

5. lseek(3, 0, SEEK_SET) = 0: Seeks to the beginning of fd 3. Read position is now 0.

6. read(3, "hello from test file\n", 256) = 21: Reads 21 bytes from fd 3 into the buffer.

7. write(1, "hello from test file\n", 21) = 21: Writes to fd 1 (stdout).

8. close(3) = 0: Closes fd 3.

9. clone(...) = 24606: This is fork. It creates a new process with PID 24606.

10. wait4(24606, NULL, 0, NULL) = 24606: Parent waits for child to exit.

11. exit_group(0): Parent exits with code 0.

Filtering strace Output: Focus on What Matters

Full strace output is noisy. Use filters to cut the signal from the noise. The -e option filters by syscall type.

strace -e openat,open,read,write,close,fork,execve ./tracetest 2>&1

Note: Modern Linux uses openat instead of open. Both do the same thing, but openat includes a directory fd for relative paths. Here is the filtered output:

open("test.txt", O_RDONLY|O_CREAT, 0644) = 3
open("test.txt", O_WRONLY|O_TRUNC, 0)  = 4
write(4, "hello from test file\n", 21) = 21
close(4)                                = 0
read(3, "hello from test file\n", 256)  = 21
write(1, "hello from test file\n", 21)  = 21
close(3)                                = 0
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_USEREGS|CLONE_VM, child_tidptr=0x7f12342a68c0) = 24618
+++ exited with code 0 +++

Much cleaner. You can also filter by syscall group. For example, -e trace=file shows all syscalls that touch the filesystem. -e trace=process shows fork, execve, exit. Combine multiple filters with commas.

Timing and Performance: -c and -T Options

To see how much time each syscall takes, use -c:

strace -c ./tracetest

Output:

% time     seconds  usecs/call     calls  syscall
------ ----------- ----------- --------- ----------------
 15.23    0.000456      114.00         4 mmap
 12.45    0.000373       62.17         6 mprotect
  9.87    0.000296       49.33         6 open
  8.34    0.000250       41.67         6 close
  7.56    0.000227       56.75         4 read
  6.12    0.000183       30.50         6 write
  5.34    0.000160       40.00         4 lseek
  4.89    0.000147       24.50         6 brk
  3.21    0.000096       16.00         6 rt_sigaction
------ ----------- ----------- --------- ----------------
100.00    0.003000              total

This tells you the percentage of time spent in each syscall, how many times each was called, and the average duration. If your program spends 50% of its time in read, you know where to optimize.

To see per-call timing, use -T:

strace -T ./tracetest 2>&1 | grep read
read(3, "hello from test file\n", 256)  = 21 <0.000012>

The <0.000012> is the time in seconds for that one syscall.

Tracing Child Processes: -f Option

When you fork, the child process is a separate process. Without -f, strace only traces the parent. With -f, it traces all children too.

strace -f -e trace=process ./tracetest

Output:

fork()                                  = 24625
[pid 24625] execve("/bin/echo", ["echo", "child process output"], [/* 54 vars */]) = 0
[pid 24625] write(1, "child process output\n", 22) = 22
[pid 24625] exit_group(0)               = ?
[pid 24624] wait4(24625, NULL, 0, NULL) = 24625
+++ exited with code 0 +++

Notice [pid 24625] in brackets. That is the child process. The parent (24624) calls wait4 to wait for the child. This is the fork/exec pattern every process on Unix follows.

File Descriptor Tracking: Why It Matters

One hidden danger in system programming is file descriptor leaks. A fd is an integer, so the kernel can run out if you open and never close. Debugging this by reading code is hard. strace shows it immediately.

Here is a program that leaks fds:

#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>

int main() {
    for (int i = 0; i < 10; i++) {
        int fd = open("test.txt", O_RDONLY);
        // Oops, forgot to close(fd);
    }
    return 0;
}

Compile and run with strace -e open,close:

strace -e open,close ./leak

You see 10 open calls and 0 close calls. The fds are leaked. A production program that does this will eventually hit the fd limit (usually 1024 per process) and start failing with "too many open files".

Digging Deeper: System Call Arguments and Return Codes

The O_RDONLY, O_WRONLY, O_CREAT flags are integers. strace decodes them for you. If you want to see the raw numbers, use -r or -v (verbose).

strace -v -e open ./tracetest

Also, strace can decode pointers and buffer contents. If you pass a struct to a syscall, strace will try to unpack it.

For example, if you use mmap:

mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1234560000

The arguments are decoded. The return value is the address where the kernel mapped memory.

Comparing: strace vs ltrace vs perf

Tool	What It Traces	Overhead	Best For
strace	System calls (kernel boundary)	High (tens of percent)	Debugging syscall behavior, fd leaks, permission issues
ltrace	Library function calls (user space)	Medium	Debugging library misuse, tracking malloc/free
perf	CPU cycles, cache misses, events	Low	Finding CPU hotspots, optimization

For low-level debugging, strace is the tool. It shows what your code asked the kernel to do. If you want to know what the code itself is doing (which functions it calls, how much time in each), use ltrace or perf.

Real World Example: Password File Reading

Suppose you are reading user data from the password file, as covered in password management. You write code to open /etc/passwd and parse it. strace shows you exactly what the system is doing:

#include <stdio.h>
#include <stdlib.h>

int main() {
    FILE *f = fopen("/etc/passwd", "r");
    if (!f) {
        perror("fopen");
        return 1;
    }

    char line[256];
    int count = 0;
    while (fgets(line, sizeof(line), f)) {
        count++;
    }

    fclose(f);
    printf("Read %d lines\n", count);
    return 0;
}

Compile and run with strace -e openat,read,close:

strace -e openat,read,close ./passwd_reader

Output (simplified):

openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
read(3, "root:x:0:0:root:/root:/bin/bash\nda...", 4096) = 3206
read(3, "", 4096) = 0
close(3) = 0

Notice that fgets does not translate to many read syscalls. The C library buffers the file. It reads 4096 bytes in one syscall, then returns one line at a time. This is why buffered I/O is fast. If you called read directly in a loop, you would see hundreds of syscalls.

Also notice O_CLOEXEC. The C library sets this flag to ensure the fd is closed if you exec. This is a security feature. If you fork and exec a child, you do not want it inheriting open fds to sensitive files.

Common Mistakes and Gotchas

Mistake 1: Assuming strace shows all the time in your program. strace adds overhead, typically 5 to 50 percent. The actual time in syscalls is usually smaller. strace is for correctness, not performance measurement. Use perf for performance.

Mistake 2: Forgetting to redirect stderr. strace writes to stderr by default. If your program also writes to stderr, it gets mixed in. Use strace ./prog 2> strace.log to separate.

Mistake 3: Not using -f when debugging multi-process programs. Without -f, you only see the parent. The child does things you never see.

Mistake 4: Misreading fd numbers. fd 0 is stdin, fd 1 is stdout, fd 2 is stderr. Any fd 3 or higher is a file or socket you opened. If you see write(4, ...), that is writing to something you opened, not to a standard stream.

FAQ

Can I attach strace to a running process?

Yes. Use strace -p PID where PID is the process id. The process pauses while strace attaches, then resumes. Use -f if the process has children you want to trace too. This is invaluable for debugging hung or slow production processes.

Why does strace show errno instead of a regular error?

When a syscall fails, the kernel sets a variable called errno and returns -1 (or -1 cast as an unsigned type). strace decodes errno for you. For example, EACCES means permission denied (errno 13). ENOENT means file not found (errno 2). The man page errno lists all codes.

How do I see the contents of buffers passed to syscalls?

Use -s SIZE to increase the buffer print size (default 32 bytes). For example, strace -s 256 shows up to 256 bytes of data in write and read calls. Non-printable bytes show as \x hex codes.

Does strace work on all programs?

Almost. You cannot strace the kernel itself or some privileged operations. Some programs with ptrace detection (like debuggers) will refuse to run under strace. Most user programs work fine. You need the same or higher privilege as the target process.

Why is my program so much slower under strace?

Because strace intercepts every syscall. The kernel pauses your process, switches to strace in supervisor mode, reads register state, formats output, writes to a file or terminal, then switches back. This happens hundreds or thousands of times. Expect 5x to 50x slowdown. For timing, use -c and subtract strace overhead, or use perf with lower overhead.

Can I log strace output to a file instead of stdout?

Yes. Use -o FILE. Also use -ff to split output by process if you are tracing children. This creates FILE.PID files, one per process.

strace is a superpower for systems programmers. It shows you the truth about what your code does at the kernel boundary. Once you learn to read the output, debugging syscall issues becomes mechanical. You see every open, read, write, and fork. You spot fd leaks immediately. You find redundant syscalls that can be removed. And when something breaks at the systems level, strace is often the first tool you should reach for.