System calls and strace

What a program asks the kernel, and its cost.

A process that is slow, stuck or failing with a vague message is usually waiting for, or being refused by, the kernel. strace shows every request a process makes to the kernel, with its arguments, its result and how long it took. This lesson uses it the way you would on a server: attach to a running process, time and count its system calls correctly, follow the child processes of a script to find the call that failed, and measure what tracing costs so you know when not to use it. What a system call is, and the first strace example, are in the essentials course's architecture lesson.

How strace works

strace is built on ptrace, the kernel interface debuggers use. When strace traces a process, the kernel stops that process at the entry and at the exit of every system call and wakes strace, which reads the call number, the arguments and the return value from the stopped process and prints them. Then it lets the process continue. That model explains both what strace can show (every call, including the ones that fail) and what it costs (two stops and two context switches per call). strace is installed with Ubuntu Server (version 6.19 on 26.04) and on RHEL 10 (6.12).

Because ptrace can read and change another process's memory, the kernel restricts it. Ubuntu enables the Yama security module's ptrace_scope restriction.

With kernel.yama.ptrace_scope = 1, a process may only trace its own descendants, unless it has the CAP_SYS_PTRACE capability. RHEL leaves it at 0, where any process may trace others of the same user. The hardening course (optional) explains the setting; the practical rule is to use sudo for a one-off trace and leave the setting alone.

Attach to a running process

The symptom: jobs dropped into a queue directory sometimes wait half a second before anything happens, and the worker process uses almost no CPU. The hypothesis is that the worker is waiting on purpose rather than working slowly. The worker is this small script. Save it as /var/tmp/pt-worker.py, create its spool directory, make it executable, and start it as a transient service under your own user.

#!/usr/bin/python3
# pt-worker: a queue worker that checks its spool directory twice a second.
import os, time
 
SPOOL = '/var/tmp/pt-spool'
while True:
    for name in sorted(os.listdir(SPOOL)):
        path = os.path.join(SPOOL, name)
        with open(path) as f:
            f.read()
        os.remove(path)
    time.sleep(0.5)

strace -p PID attaches to a running process; pgrep -x finds the PID by the exact process name. The worker belongs to you, but systemd started it, so it is not a descendant of your shell and Yama refuses. With sudo it works. -T adds the time spent in each call in angle brackets. strace runs until you press Ctrl-C; here timeout -s INT 2 sends the same signal after two seconds. strace then detaches and the worker carries on as before.

Each round the worker opens the spool directory, reads its entries with getdents64 (only . and .., so the second call returns 0), closes it, and then sits in clock_nanosleep for about 0.5 seconds. That confirms the hypothesis: a job waits for the next poll, up to half a second, and nothing is slow. The fix is in the design (a shorter interval, or inotify to be woken when a file arrives), not in the system. The last call was still running when strace detached, so it ends in <detached ...>.

Counting calls: CPU time or wall-clock time

For a busy process, a line per call is too much to read, and -c prints a summary table instead: calls, errors and time per system call. What the time column measures is the part most people get wrong. By default strace -c sums system time, the CPU time the kernel spent executing each call. -w switches it to wall-clock time, from the start of the call to its end, including the time the process was blocked.

The default table adds up 4 milliseconds of kernel CPU time in five seconds. clock_nanosleep leads it with 2.3 ms, the CPU cost of setting up ten sleeps (in other runs openat came first), and nothing in the table says where the five seconds went. With -w the same five seconds are 99.90% clock_nanosleep, 4.9 seconds of waiting, which is what the worker actually does. A call that blocks, such as a sleep, a read from an idle socket, a futex wait on a lock or epoll_wait, uses almost no CPU while it waits, so without -w it can take seconds and still rank at the bottom. When the kernel works hard inside the calls, the two views agree.

dd copying 2 GB from /dev/zero spends its time inside read, where the kernel fills the buffer with zeros, so read leads both tables (0.106 s of CPU time, 0.149 s of wall-clock time; the rest of the wall-clock figure is the tracing itself). Use plain -c to ask where the kernel spends CPU on behalf of a process, and -c -w to ask where the time goes, which is the question when something is slow. For a multi-threaded program, -p alone attaches only the thread with that ID; add -f to attach every thread. Expect futex near the top of a -w table even in a healthy program, because idle worker threads also wait in futex; the question is which thread waits, and what it waits for.

RHEL gives the owner of a process more room: with ptrace_scope 0, the same attach works without sudo.

On Rocky the worker runs as python3 /var/tmp/pt-worker.py, because SELinux does not let systemd execute a script stored in /var/tmp (the unit fails with status=203/EXEC). strace 6.12 attaches without sudo and shows the same wall-clock picture.

Follow child processes and filter the calls

The next symptom is a script that prints "report failed" and nothing else, because it sends its commands' errors to /dev/null, as many real scripts do.

#!/bin/bash
# pt-report.sh: summarise the day's sales (like many scripts, it hides the real error)
cd /var/tmp/pt-lab || exit 1
if ! sort -t, -k2 -n data/sales.csv > /dev/null 2>&1; then
  echo 'report failed'
  exit 1
fi
echo 'report ok'

To reproduce it, create /var/tmp/pt-lab, save the script there, make it executable, and give it a small data file. -e trace=openat limits the output to file opens. Without -f, strace traces only the process it started.

The only opens shown are bash's own: its libraries, locale files and the script. The work happened in a child process, and the only trace of it is the SIGCHLD line: a child exited with status 2. -f follows every child and thread, and -Z (--failed-only) prints only calls that returned an error.

Lines from other processes carry [pid N]. Skipping bash's locale lookups (failed attempts that are normal, because glibc tries several file names), the child sort tried to open data/sales.csv relative to /var/tmp/pt-lab and got ENOENT: the file is sales.csv in that directory, not in a data subdirectory. The other two attached processes are sort's threads. -e trace= also takes classes: %file for every call that takes a file name, %process for fork, exec and wait, %network for sockets. -o FILE writes the trace to a file, and -s 200 prints longer strings than the default 32 characters.

What tracing costs

Two stops per system call are cheap for a process that makes a few calls a second and ruinous for one that makes hundreds of thousands. dd with a block size of one byte makes a read and a write for every byte, and prints its own timing.

100,000 bytes take 0.057 seconds without tracing and 11.4 seconds under strace, even with the output thrown away: the stops themselves are the cost, about two hundred times here. Filtering with -e trace= alone does not help, because strace still stops the process on every call and discards the ones you did not ask for. --seccomp-bpf does help: strace installs a seccomp filter in the traced process so the kernel stops it only for the traced calls, and the run takes 0.057 seconds, the same as without strace. It works only for a process strace starts (with -f), not with -p.

perf trace reads the kernel's system call tracepoints (the hooks the eBPF tools lesson uses) instead of stopping the process.

It took 1.7 seconds on the same workload, far less than strace's 11.4 but about 30 times the untraced run, and -s prints a per-call summary with wall-clock times. Ubuntu's perf is built without the BPF skeletons that perf trace uses to copy string arguments, so it shows file names as pointer values; for arguments, strace is still the tool. The eBPF tools lesson covers tracing that aggregates in the kernel.

Try this

Watch the worker pick up a job. It is still running from the attach section (if you stopped it, start it again with the same systemd-run command). In one command line, trace only openat and unlinkat in the background for three seconds, and drop a file into the spool while it runs. Predict the order before you look: the directory open on every poll, then the open of job-1 and its removal (unlinkat) in the round after the file appears; the strace: Process ... attached line first, and detached when timeout sends SIGINT. Then compare with the lab's run, and stop the worker.

Takeaway

When a process is slow, time its calls with strace -c -w (and -f for threads), because the default summary counts only CPU time; and keep strace for processes that make few calls or that you can start with --seccomp-bpf, because every traced call stops the process twice.

Related