Skip to content
vivek pal

wiki / linux

reading a slow system

A triage order for a Linux box that feels slow, from the first sixty seconds down to perf and bpftrace.

updated · 5 min read

“Slow” means some resource is saturated or something is waiting. Start wide, find the resource, then narrow down to the process and the code path. The tools get sharper and more expensive as you go down.

the first minute

The opening list comes from Brendan Gregg and the Netflix performance team, in Linux Performance Analysis in 60,000 Milliseconds. Run them in order:

uptime
dmesg | tail
vmstat 1
mpstat -P ALL 1
pidstat 1
iostat -xz 1
free -m
sar -n DEV 1
sar -n TCP,ETCP 1
top

What each one is for:

  • uptime gives 1, 5 and 15 minute load averages. On Linux, load counts tasks waiting for disk I/O (state D) as well as runnable tasks (state R), so a high load doesn’t prove the CPUs are busy. A 1-minute value well above the 15-minute value means load is rising.
  • dmesg | tail catches the loud failures: OOM kills, dropped packets, disk errors.
  • vmstat 1: r is runnable tasks; if it stays above the CPU count, the CPUs are saturated. b is tasks blocked on I/O. Non-zero si/so means the box is swapping. Then us, sy, id, wa (waiting on I/O) and st (time stolen by the hypervisor). A steady wa points at the disk.
  • mpstat -P ALL 1 shows each CPU. One core pinned while the rest idle is a single-threaded bottleneck.
  • pidstat 1 is a rolling per-process view. -d adds I/O, -r page faults and memory, -w context switches, -t threads.
  • iostat -xz 1, where -z hides idle devices. r_await and w_await are milliseconds per request, queue time included, which is the latency the application feels. aqu-sz is the average queue length (older sysstat calls it avgqu-sz). %util near 100% means saturation only for devices that serve requests one at a time. SSDs and RAID arrays work in parallel, so trust await over %util there.
  • free -m: read the available column. It estimates memory a new program can get without swapping, page cache included.
  • sar -n DEV 1 shows interface throughput, which you compare against link speed. sar -n TCP,ETCP 1 shows connection rates and retransmits.
  • top to confirm what the others suggested.

pressure stall information

If /proc/pressure/ exists, the kernel tracks how much time tasks spend stalled on CPU, memory and I/O. It answers the question the tools above circle around: is anything waiting, and how much?

cat /proc/pressure/memory
some avg10=0.00 avg60=0.00 avg300=0.00 total=0
full avg10=0.00 avg60=0.00 avg300=0.00 total=0

some is the share of time at least one task was stalled on that resource. full is the share of time every non-idle task was stalled at once, which is when throughput is really lost. avg10, avg60 and avg300 are percentages over 10 s, 60 s and 5 min windows, and total is the absolute stall time. CPU full has no meaning at the system level and reads zero. With cgroup v2, each cgroup has its own cpu.pressure, memory.pressure and io.pressure, which tells you which service is the one waiting.

one process: strace

Once you have a suspect PID, see what it asks the kernel for.

strace -c -p 1234                                  # Ctrl-C after a few seconds
strace -f -T -e trace=openat,read,write -p 1234

-c prints calls, errors and time per syscall. That time is CPU time in the kernel, not wall-clock time, so a process blocked in futex or poll can look cheap here; add -w to summarize wall-clock time instead. -T prints the time spent inside each call, -f follows child processes and threads, and -e trace= narrows the set.

strace stops the target on every syscall it traces, so it can slow it down a lot. Keep runs short on a box that serves traffic.

CPU: perf

When a process burns CPU, sample its stacks.

perf top -g                              # live view with call graphs
perf record -F 99 -a -g -- sleep 30      # sample every CPU at 99 Hz for 30 s
perf report --stdio

99 Hz rather than 100 avoids sampling in lockstep with work that runs on a 100 Hz timer. -a records every CPU; use -p PID for one process. Call graphs default to frame pointers, and code built without them gives broken stacks. Switch the unwinder:

perf record -F 99 --call-graph dwarf -p 1234 -- sleep 30

Function names showing up as hex addresses mean symbols are missing; install the debug package for that binary. For a picture instead of a text report, Gregg’s FlameGraph scripts turn perf script output into an SVG:

perf script | ./stackcollapse-perf.pl | ./flamegraph.pl > cpu.svg

bpftrace one-liners

bpftrace attaches small programs to kernel and user events with far less overhead than strace. These come from the bpftrace one-liner tutorial and need root.

# syscalls per process
bpftrace -e 'tracepoint:raw_syscalls:sys_enter { @[comm] = count(); }'

# files being opened, and by whom
bpftrace -e 'tracepoint:syscalls:sys_enter_openat { printf("%s %s\n", comm, str(args.filename)); }'

# vfs_read latency per process, as a histogram in nanoseconds
bpftrace -e 'kprobe:vfs_read { @start[tid] = nsecs; } kretprobe:vfs_read /@start[tid]/ { @ns[comm] = hist(nsecs - @start[tid]); delete(@start, tid); }'

# block I/O request sizes
bpftrace -e 'tracepoint:block:block_rq_issue { @ = hist(args.bytes); }'

# on-CPU kernel stacks at 99 Hz
bpftrace -e 'profile:hz:99 { @[kstack] = count(); }'

Older releases spell tracepoint arguments args->filename. If one of these fails to parse, check the version and the syntax first.

when nothing looks busy

CPUs idle, disks quiet, and the app is still slow: the time is going into waiting. Lock contention, a DNS lookup, a remote call, a sleep in a retry loop. Look at where tasks leave the CPU:

bpftrace -e 'tracepoint:sched:sched_switch { @[kstack] = count(); }'

Then go back to strace -T on the process and find the call that blocks.

sources

← all notes