📈Module 14 — Performance Methodology & Tracing

 11:57:45 up  4:49,  0 user,  load average: 0.21, 0.17, 0.18

procs -----------memory---------- ---swap-- -----io---- -system-- -------cpu-------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st gu
 2  0      0 5796084  20376 1754580    0    0   169   100  992    7  2  3 96  0  0  0
 2  0      0 5796780  20376 1754600    0    0     0     0  922  955 97  3  0  0  0  0
 2  0      0 5796840  20376 1754600    0    0     0     0  656  755 97  3  0  0  0  0

Average:     CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest  %gnice   %idle
Average:     all   96.48    0.00    3.02    0.00    0.00    0.00    0.00    0.00    0.00    0.50
Average:       0   98.99    0.00    1.01    0.00    0.00    0.00    0.00    0.00    0.00    0.00
Average:       1   94.00    0.00    5.00    0.00    0.00    0.00    0.00    0.00    0.00    1.00

What to read out of this — and notice how much three commands settled.

uptime answers "is this new?" Three seconds after starting two CPU burners it shows nothing: 0.21 0.17 0.18, essentially flat. That is the first lesson, and it is better than the one you were expecting. The load average is a 1-, 5- and 15-minute exponentially weighted moving average, sampled every five seconds — three seconds of two runnable tasks can add at most about 0.1 to the first figure. Use uptime to answer "has this been going on a while?", and never "did something just start?" — vmstat's r column answers that instantly. (Leave the burners running for 45 seconds and re-run it, and you will watch the first number climb away from the other two.)

vmstat answers "which resource?" Ignore the first line's rate columns — bi, bo, in, cs, us, sy, id, wa are averages since boot, not a sample, and misreading them is the most common vmstat mistake. (r, b and the memory columns are current, which is why r already reads 2 on that first line.) On the real samples: r is 2 with 2 CPUs, so the run queue is full but not backed up. us is 97 and sy is 3, so this is application work, not kernel work. wa is 0, so nothing is waiting on disk. si/so are 0, so there is no swapping. b is 0, so nothing is blocked. Four whole categories of cause eliminated in three lines.

mpstat -P ALL answers "everywhere, or one place?" Both CPUs are near 100%, so this is genuinely CPU-bound work spread across the machine. Had one CPU been at 100% and the rest idle, the story would be a single-threaded bottleneck, and the fix would be completely different.

Check %steal every time you look at this on a VM. It is 0 here. Anything sustained above a few percent means the hypervisor took your CPU away, and no amount of optimising your code will help.

If your vmstat has no gu column, you are on an older procps. It is guest time, and on most hosts it is zero.

===== CPU =====
-- utilization
11:59:21     all    1.02    0.00    4.57    0.00    0.00    0.00    0.00    0.00    0.00   94.42
-- saturation: r should be <= 2
 0  0      0 5796840  20376 1754600    0    0     0     0  656  755  1  4 95  0  0  0
-- saturation: PSI
  no /proc/pressure - PSI not enabled on this kernel
===== MEMORY =====
-- utilization
               total        used        free      shared  buff/cache   available
Mem:            8023         852        5686           4        1733        7170
Swap:              0           0           0
-- errors
0
===== STORAGE =====
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.51    0.00    4.55    0.00    0.00   94.95

Device            r/s     rkB/s   rrqm/s  %rrqm r_await rareq-sz     w/s     wkB/s ...

===== NETWORK =====
Average:         eth0      8.00      8.00      1.20      2.03      0.00      0.00      0.00      0.00
Average:      docker0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
-- errors
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN mode DEFAULT group default
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    RX:  bytes packets errors dropped  missed   mcast
     703885134  102123      0       0       0       0

What to read out of this.

Memory is the line most people misread. free is 5686 MB and available is 7170 MB — available is larger, because most of buff/cache is reclaimable page cache the kernel will hand back on demand (Module 09). Always read available. A monitoring alert on free will page you about a perfectly healthy machine every single time.

The storage section shows an empty device list, and that is -z doing its job: it omits devices with no activity in the interval. An empty table means an idle disk, not a broken command. It is also worth knowing that in a container, or on overlay and network storage, the device you think you are using may not appear as a block device at all — which is itself a finding.

/proc/pressure is missing here. PSI needs CONFIG_PSI=y, and on kernels built with CONFIG_PSI_DEFAULT_DISABLED=y it additionally needs psi=1 on the kernel command line. When it is present it is the best saturation signal on the machine, because it measures the thing USE calls saturation directly rather than by proxy. Check for it once per platform, and if it is missing, say so in the runbook rather than letting people wonder.

The network errors block is the one nobody checks. errors and dropped at zero is the answer you want. Non-zero and growing is a real finding, and it is invisible in every CPU and memory dashboard ever built.

mean      20.6 ms
p50        9.9 ms
p90       14.0 ms
p95       14.6 ms
p99       15.0 ms
p99.9   1115.1 ms

requests slower than the mean: 10 of 1000 (1.0%)

What to read out of this. Look at the mean and the p99 together: 20.6 ms and 15.0 ms.

The mean is higher than the p99. That is not a mistake and it is not unusual — it is what happens whenever a small number of requests are enormously slower than the rest, which is the normal shape of real latency. The mean is being dragged upward by ten requests out of a thousand, and it now describes 1% of your traffic. Ninety-nine percent of users had a better experience than "average".

And the mean hides the thing that matters. The disaster in this data is p99.9 = 1115.1 ms — someone waited over a second. (Note that p99.9 of a thousand samples is rank 999, not rank 1000; rank 1000 is the maximum. With this few requests the tail rests on a single data point, which is itself worth remembering.) A dashboard showing "average latency 20 ms, well within SLO" is green while that is happening, every minute of every day.

p50 = 9.9 ms is the typical experience. The gap between p50 and p99.9 — a factor of over a hundred — is the number worth tracking, because it is a measure of how consistent the service is, and consistency is what people actually notice.

Read the percentiles as a shape, not as four numbers. p50 to p99 barely moves (10 → 15 ms): the fast path is tight and healthy. Then p99 to p99.9 explodes. A flat body with a cliff at the tail means a distinct, occasional event — a garbage-collection pause, a cache miss going to disk, a lock, a retry. A gradually rising curve with no cliff means the whole system is loaded. The two have completely different fixes, and the mean tells you neither.

Your exact numbers will differ, because mawk and gawk use different random number generators from the same seed. These figures are from mawk 1.3.4, which is /usr/bin/awk on Debian and Ubuntu; gawk gives a mean of 19.8 and a p99.9 of 1190.0. The shape — mean above p99, exactly ten requests above the mean, a hundredfold gap from p50 to p99.9 — holds on both, and the shape is the point.

throughput 1200 req/s, latency 45 ms -> in flight L = 54.0
200 workers at 100 ms each -> ceiling = 2000 req/s
util     latency multiplier 1/(1-u)
50            2.0x
70            3.3x
80            5.0x
90           10.0x
95           20.0x
99          100.0x

What to read out of this.

54 in flight is the number that settles arguments about pool sizes. If the connection pool is 20, the service cannot possibly be doing 1,200 req/s at 45 ms — either the latency is higher than reported, or requests are queueing before they reach the pool where your latency metric never sees them. That second case is extremely common and extremely hard to see: the request has arrived, the clock is running, and your instrumentation has not started yet.

The 2,000 req/s ceiling is the same arithmetic run backwards, and it is how you answer "will this handle Black Friday?" without a load test. Note what it means: past 2,000, throughput stops rising and latency absorbs the difference. The graph does not fall over — it goes flat while the latency graph climbs, which is why "throughput looks fine" is not evidence of health.

The multiplier column is the important half. The ten-point step from 70% to 80% adds 1.7 to the multiplier (3.3× → 5.0×). The very next ten-point step, 80% to 90%, adds 5.0 (5.0× → 10.0×). Same step on the gauge, three times the damage — and every capacity plan built on "keep it under 80%" is really a plan to stay on the flat part of that curve.

These are idealised M/M/1 figures, and a real system's curve is different in detail — more servers push the knee later, variable service times pull it earlier. The shape is universal, and the shape is the lesson.

Resist naming a tool. The answer that lands is a method, described in three moves.

First, define "slow" and scope it. Slow for whom, since when, and is it every request or a fraction? Is it this host or the whole fleet? A single host in a load-balanced pool that is slow is a completely different investigation from all of them being slow, and it costs one question to find out.

Second, run a fixed checklist rather than a favourite command. uptime for the trend, vmstat 1 and mpstat -P ALL 1 for where the time goes, free -m, iostat -xz 1, sar -n DEV 1, pidstat 1, dmesg | tail. Sixty seconds, and it eliminates whole categories: CPU-bound versus I/O-bound versus memory-pressured versus not-the-host-at-all.

Third, go where the checklist points, and only then reach for perf or a tracer.

The details that separate candidates: naming the method — the USE method, one question each for utilization, saturation and errors across CPU, memory, disk and network — and saying what happens when it comes back clean. That is not a dead end; it is the finding that moves you from the host to the request path, where you look at RED or the Golden Signals instead. Adding "and I check %steal first on a VM, because if the hypervisor is taking the CPU, nothing I do on this box matters" is a strong, concrete finish.

This is the classic, and the answer is a fact about Linux specifically: the run queue that feeds the load average includes uninterruptible-sleep (D state) tasks, not just runnable ones. On other UNIXes, load average is a CPU-demand metric. On Linux it is a "tasks that want to be making progress" metric, and a process blocked on disk or on an NFS server that has gone away counts.

So high load with idle CPU almost always means processes are blocked, not computing. Find them: ps -eo state,pid,comm | awk '$1 ~ /^D/', and then cat /proc/<pid>/stack or /proc/<pid>/wchan to see what they are blocked in.

The usual causes are a slow or failing disk, an NFS or network filesystem timing out, or heavy writeback flushing. iostat -xz 1 and the b column of vmstat confirm it in seconds.

The details that separate candidates: pointing out that iowait is not a fifth kind of busy — it is a subset of idle, time when the CPU had nothing to run and at least one task was waiting on I/O. So low %iowait does not rule out an I/O problem: if there is other work to run, the CPU is counted busy instead. Then adding the diagnostic that beats both: /proc/pressure/io, which measures stall directly. And knowing that a load average of 8 on a 64-core machine is nothing at all, so the number is meaningless without nproc.

Latency, Traffic, Errors, Saturation — from chapter 6 of Google's Site Reliability Engineering.

Latency is how long a request takes; traffic is how much demand there is; errors is the rate of failing requests, including the implicit kind (an HTTP 200 with wrong content) and the policy kind (over a second when your SLO says under a second); saturation is how full the service is, focusing on whichever resource is most constrained.

RED — Rate, Errors, Duration — is the same idea minus saturation, named at Weaveworks by Tom Wilkie, and it maps neatly onto per-service dashboards.

The details that separate candidates: two things. First, that latency must be split into successful and failed requests, because fast failures make the latency graph look better while the service is broken — that is straight out of the SRE book and almost nobody says it. Second, that Golden Signals and RED are request-oriented and USE is resource-oriented, and you want both: one tells you users are suffering, the other tells you which resource to fix. Being able to say "RED is the Golden Signals minus saturation, and that is exactly the gap USE fills" shows you understand them as a system rather than as two lists you memorised.

First establish that it is real and scope it. Is the request count stable? A p99 computed over eleven requests is noise. Is it one endpoint, one host, one customer, one availability zone — or everything? Slicing by those four dimensions usually ends the investigation before any tool comes out, because a jump on one host is a host problem and a jump on one endpoint is a code or query problem.

Then look at the shape. Did p50 move too? p50 flat with p99 up means an occasional discrete event: a garbage-collection pause, a cold cache going to disk, a lock, a retry after a timeout. p50 up as well means the whole system is loaded, and the question becomes which resource.

Then correlate with what changed. Deploy, config push, feature flag, traffic increase, a dependency's own latency, or a cron job that starts at the same minute every day. Overlay the p99 graph on the deploy markers first — it is free and it is right surprisingly often.

Then go to the host with the USE checklist, and only then to a profiler.

The details that separate candidates: mentioning the queueing knee — if utilization crept from 80% to 90%, the tail doubling is not a bug, it is 1/(1−u), and the fix is capacity rather than code. Mentioning retry amplification, where a small latency rise triggers client timeouts and retries that add load exactly when there is none to spare. And the metrics-hygiene point: if your p99 is computed by averaging per-host p99s, the number is meaningless and the first fix is to store histograms.

Start from demand, not from servers. Get a traffic forecast with a unit that means something to the business — orders per second, active users, messages per minute — and its growth rate and seasonality, including the one annual peak everyone forgets.

Then find the actual ceiling by measurement, not by guess: load-test a single instance to saturation and record where latency leaves the flat part of the curve. That is your usable capacity per instance, and it is nearly always well below 100% CPU.

Then apply Little's Law to size the pieces: in-flight = throughput × latency tells you thread pools, connection pools and queue depths, and shows you where a limit you set years ago has become the bottleneck.

Then add headroom for the failure you plan to survive — losing one zone of three means each survivor must carry 50% more — and set an alert on the leading indicator, not on the gauge.

The details that separate candidates: refusing the "we're at 80%, so we have 20% headroom" framing out loud, and explaining why with the 1/(1−u) curve. Also separating vertical from horizontal: vertical is quick, bounded and does nothing for availability; horizontal is the real answer but only if the workload has no single-instance state and the downstream — usually the database — can take the extra connections. Finishing with "and I plan for the constraint I measured, which is usually not CPU" is a good, honest note: it is far more often a connection limit, a lock, or a single-threaded section.

 12:02:38 up  4:54,  0 user,  load average: 0.38, 0.23, 0.19

[14001.537519] veth485ad0a (unregistering): left promiscuous mode
[14001.538750] docker0: port 1(veth485ad0a) entered disabled state

procs -----------memory---------- ---swap-- -----io---- -system-- -------cpu-------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st gu
 2  0      0 5796084  20376 1754580    0    0   169   100  992    7  2  3 96  0  0  0
 2  0      0 5796780  20376 1754600    0    0     0     0  922  955 97  3  0  0  0  0
 2  0      0 5796840  20376 1754600    0    0     0     0  656  755 97  3  0  0  0  0

Average:     all   96.48    0.00    3.02    0.00    0.00    0.00    0.00    0.00    0.00    0.50
Average:       0   98.99    0.00    1.01    0.00    0.00    0.00    0.00    0.00    0.00    0.00
Average:       1   94.00    0.00    5.00    0.00    0.00    0.00    0.00    0.00    0.00    1.00

Average:      UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
Average:        0         1    0.00    2.00    0.00    0.00    2.00     -  process_api
Average:        0     27896   99.00    1.00    0.00    0.00  100.00     -  bash
Average:        0     27901   98.00    2.00    0.00    0.00  100.00     -  bash

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          96.98    0.00    3.02    0.00    0.00    0.00

Device            r/s     rkB/s   rrqm/s  %rrqm r_await rareq-sz     w/s     wkB/s ...

               total        used        free      shared  buff/cache   available
Mem:            8023         852        5686           4        1733        7170
Swap:              0           0           0

Average:         eth0      8.00      8.00      1.20      2.03      0.00      0.00      0.00      0.00

Average:     atmptf/s  estres/s retrans/s isegerr/s   orsts/s
Average:         0.00      0.00      0.00      0.00      0.00

What to read out of this, command by command — the value is in what each one removes.

1. uptime — 1.42, 0.71, 0.35, rising steeply. Something started recently. If those numbers had been falling you would already be looking at the aftermath of an event, which is a very different conversation.

2. dmesg — the last lines are Docker tearing down a veth pair. Unrelated, and that is the point: you are looking for Out of memory: Killed process, I/O error, blocked for more than 120 seconds, or a link flapping. None present, so a whole class of hardware and OOM causes is eliminated for free.

3. vmstat 1 — skip the first line, always: it is an average since boot, not a sample. On the real samples, r=2 on a 2-CPU box, b=0, si/so=0, us=97, sy=3, wa=0. That is four eliminations in one screen: no swapping, nothing blocked, no I/O wait, and the work is in user space, not the kernel. If sy had been 97, you would be looking at system calls or interrupts and the rest of this module would take a different path.

4. mpstat -P ALL — both CPUs near 100%, so the load is spread. One CPU pinned with the rest idle would mean a single-threaded bottleneck, and adding cores would not have helped. %steal is 0.00, so the hypervisor is not the problem.

5. pidstat 1 — two bash processes at 100% each. Now, and only now, you have a suspect. Note pidstat rolls, printing a fresh block each interval, so it captures a short-lived spike that top would have redrawn away.

6. iostat -xz — the CPU line agrees with mpstat (near-zero idle), and there are no device rows at all, because -z omits devices with no activity in the interval. The disk is doing nothing. Confirms wa=0.

7. free -m — available is 7170 of 8023 MB. Plenty. Read available, never free.

8 and 9. sar -n — 8 packets/s and zero retransmits, zero failed connects, zero resets. The network is idle and healthy. Command 9 is the one people skip, and it is the one that catches a sick network as opposed to a busy one.

The conclusion after sixty seconds: user-space CPU work, spread over both cores, from two named processes, with disk, memory, network and hypervisor all ruled out. That is not a guess about where to look next — it is the only place left, and Part C is how you look there.

--- vmstat: line 1 is an average SINCE BOOT ---
procs -----------memory---------- ---swap-- -----io---- -system-- -------cpu-------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st gu
 0  0      0 5796084  20376 1754580    0    0   169   100  992    7  2  3 96  0  0  0
 0  0      0 5796780  20376 1754600    0    0     0     0  312  455  1  4 95  0  0  0
 0  0      0 5796840  20376 1754600    0    0     0     0  289  401  1  3 96  0  0  0

load 0.14 over 2 CPUs = 0.07 per CPU

processes in D state: 0

--- 1.2 GB write, CPU otherwise idle ---
12:04:52     all    1.03    0.00   49.48    0.00    0.00    0.00    0.00    0.00    0.00   49.48
12:04:53     all    0.51    0.00   52.04    0.00    0.00    0.51    0.00    0.00    0.00   46.94
12:04:54     all    1.02    0.00   52.04    0.00    0.00    1.02    0.00    0.00    0.00   45.92
Average:     all    0.85    0.00   51.19    0.00    0.00    0.51    0.00    0.00    0.00   47.44

What to read out of this.

Block 1: look at bi, bo and cs. The first line says 169 and 100 blocks and only 7 context switches; the real samples say 0, 0 and several hundred. Those columns are averages over the machine's entire uptime — hours of history compressed into one row that looks exactly like a measurement. Note that only the rate columns are affected: r, b and the memory columns on that first line are current values. Discard it every single time, in vmstat and in iostat. sar, mpstat and pidstat are exempt — their first interval is a genuine sample. Whole incident calls have been spent on this one.

Block 2: 0.07 per CPU. The raw load average is the number people quote and it carries no information on its own. A load of 8 is an emergency on a 2-core box and idle on a 64-core one; divide before you react.

Block 3: zero processes in D state. This is the command to run when load is high and CPU is idle — D is uninterruptible sleep, it counts towards the load average on Linux, and it is almost always disk or a network filesystem. When you find one, cat /proc/<pid>/wchan names the kernel function it is stuck in.

Block 4 is the surprise, and it is real. A 1.2 GB write with an idle CPU produced %iowait of 0.00 and %sys of about 52 — the write went through virtualised storage, so the cost appeared as kernel CPU time, not as waiting. On this class of machine %iowait never rises at all.

That generalises further than it looks. %iowait is already a subset of idle, so a busy CPU hides it — and on virtio, overlay, network-backed or NVMe storage it can stay near zero even on a completely idle CPU. Never conclude "no disk problem" from a low %iowait. Use iostat -xz's r_await/w_await and aqu-sz, or /proc/pressure/io where PSI exists. Your own numbers here will differ by storage type, and finding out which shape your platform has is the whole reason to run it.

vmstat 1 (the wa column and the b column), mpstat -P ALL 1 (%iowait per CPU), and iostat -xz 1 for the per-device picture — where the numbers that matter are r_await and w_await (average latency in milliseconds) and aqu-sz (average queue depth), not %util.

A low %iowait proves almost nothing, and this is the real answer. It is defined as time the CPU was idle with at least one I/O outstanding. If the CPU has other work, that time is counted as busy instead, and %iowait stays near zero while the disk is the bottleneck. It can also stay near zero on virtualised, overlay or network-backed storage, where the cost shows up as system time instead.

The reliable signals are per-device latency from iostat, the count of processes in D state, and — best of all — /proc/pressure/io, which measures stall directly rather than inferring it from idleness.

The details that separate candidates: saying that %util is meaningless on any device that serves requests in parallel. It measures the fraction of time at least one request was in flight, so an NVMe drive handling 32 concurrent requests can show 100% while at a few percent of its real capacity. Knowing that svctm was removed from sysstat in 12.1.2, and that avgqu-sz had already been renamed aqu-sz a release or two earlier, is a nice touch, because it shows you have read the current tool rather than a 2014 blog post.

Not on its own — and answering "yes" is the trap. A batch job, a compile, or a video encode should use 100% CPU; that is the resource being used, which is what you bought it for. Utilization is not a problem. Saturation is.

The follow-up questions are: is the run queue longer than nproc (vmstat 1, column r)? Is /proc/pressure/cpu non-trivial? Is latency actually worse? If the answer to all three is no, the machine is being used efficiently and there is nothing to fix.

And two clarifying checks: mpstat -P ALL 1, because one pinned CPU with the rest idle is a single-threaded bottleneck rather than a busy machine; and %steal, because on a VM the CPU may not really be yours.

The details that separate candidates: raising the container case unprompted. Inside a container, top usually reports a percentage of the host's CPUs, not of the cgroup quota — so a container limited to 0.5 CPU can show 50% and be completely throttled. The number that tells the truth is nr_throttled and throttled_usec in cpu.stat. Being throttled at 40% reported CPU is one of the most common and most confusing production symptoms there is.

Time your virtual CPU was runnable but not scheduled, because the hypervisor gave the physical core to someone else. It is involuntary and it is invisible to the application, which simply experiences everything taking longer.

Three causes, three different fixes: a noisy neighbour on an oversubscribed host (move, or pay for dedicated tenancy); burstable-instance credit exhaustion on T-series-style instances, where you are being throttled to a baseline (change instance family, not code); or your own hypervisor being overcommitted, if you run it.

The details that separate candidates: stating plainly that %steal is the one performance number you cannot act on from inside the machine — no amount of profiling, tuning or optimising changes it — so checking it early prevents an entire wasted investigation. And knowing that it appears in mpstat, vmstat (st), top and sar -u, so there is no excuse for not looking; most people simply have never been told what the column is.

747
  alignment-faults                                   [Software event]
  bpf-output                                         [Software event]
  cgroup-switches                                    [Software event]
  context-switches OR cs                             [Software event]
  cpu-clock                                          [Software event]
  cpu-migrations OR migrations                       [Software event]

 Performance counter stats for 'sleep 0.2':

              0.98 msec task-clock                       #    0.005 CPUs utilized
                 1      context-switches                 #    1.024 K/sec
                63      page-faults                      #   64.538 K/sec
   <not supported>      cycles
   <not supported>      instructions

       0.202089319 seconds time elapsed

       0.001388000 seconds user
       0.000000000 seconds sys

 Performance counter stats for 'timeout 2 bash -c x=0; while :; do x=$((x+1)); done':

           1975.52 msec task-clock                       #    0.987 CPUs utilized
                71      context-switches                 #   35.940 /sec
                 2      cpu-migrations                   #    1.012 /sec
               224      page-faults                      #  113.388 /sec

       2.002121914 seconds time elapsed

       1.975273000 seconds user
       0.000000000 seconds sys

What to read out of this.

<not supported> on cycles and instructions is the deliberate failure, and it is the normal state of a cloud VM. No virtual PMU is exposed, so the hardware counters simply are not there. Nothing is misconfigured and no permission will fix it. Every "measure your IPC" tutorial stops working right here, and knowing that in advance saves an hour.

task-clock versus seconds time elapsed is the single most useful ratio in perf stat. 1975.52 msec of CPU across 2.002 seconds of wall clock is 0.987 CPUs utilized — the process was on CPU essentially the whole time it existed. That is a CPU-bound workload, and a CPU profile will be informative.

Compare sleep 0.2: 0.98 msec of CPU across 0.202 seconds is 0.005 CPUs utilized. That process spent 99.5% of its life off CPU. Profiling it for CPU time would produce an empty and completely honest flame graph, and the real question would be what it was waiting for.

Read that ratio before you profile anything. Near 1.0 per thread means CPU-bound, so sample the CPU. Near 0 means blocked, and the answer is in Part D, not in a flame graph.

user versus sys narrows it further. Here it is 1.975 user and 0.000 system: pure user-space computation, no kernel involvement. Had sys dominated, the next tool would be a syscall tracer rather than a profiler.

71 context switches and 2 migrations over two seconds is nothing. Thousands per second would suggest lock contention or an over-threaded application, and perf stat is the cheapest way to spot it.

[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.090 MB /tmp/perf.data (486 samples) ]

task-clock:ppp

# Samples: 486  of event 'task-clock:ppp'
# Event count (approx.): 4909090860
#
# Overhead  Command  Shared Object      Symbol
# ........  .......  .................  ...................................
#
     7.61%  bash     libc.so.6          [.] __strlen_evex
            |
            ---__strlen_evex
               |
               |--1.65%--print_simple_command
               |          0x55b14d842219
               |          execute_command_internal
               |          execute_command

9041
174
bash;_start;__libc_start_main@@GLIBC_2.34;...;execute_command_internal;[bash] 242424240
bash;_start;__libc_start_main@@GLIBC_2.34;...;execute_command_internal;[bash];[bash] 181818180

-rw-r--r-- 1 root root 52429 Aug 22 12:11 /tmp/cpu.svg

What to read out of this.

Look at line 2: the event is task-clock:ppp, not cycles. (Run as an ordinary user it reads task-clock:upppH instead — u because perf_event_paranoid = 2 restricts you to user-space events, H for host. Same fallback, extra modifiers.) You did not ask for that. perf record defaults to the hardware cycles event, found no PMU on this VM, and silently fell back to a software timer. That is good behaviour and it is worth knowing about, because your samples are now measured in wall-clock time on CPU rather than in cycles — fine for finding hot functions, useless for anything about instructions-per-cycle. Always run perf evlist on a profile before you draw conclusions from it. The :ppp suffix is the precision modifier, requesting maximum precision.

486 samples over 5 seconds at 99 Hz is what you expect from roughly one busy CPU: 99 × 5 ≈ 495. If your sample count is far below that, the process was not on CPU as much as you thought — which is a finding, not a problem with perf.

perf report is often the whole answer, and people skip straight past it to the picture. Here the top symbol is __strlen_evex in libc at 7.61% — a shell spinning on arithmetic spends its time in string handling, which is exactly right for bash and would surprise anyone who assumed the loop was doing arithmetic. --no-children shows self time, the time actually in each function; without it you get cumulative time including callees, and the top entry is always _start, which tells you nothing.

The pipeline shrinks the data enormously: 9041 lines of perf script become 174 folded lines. Each folded line is one unique stack plus a count, so it is greppable — grep mysql out.folded before drawing is a very effective way to answer "how much time is in the database driver?".

And now the flaw that Section C3 is about. Look at the folded stacks: they are full of [bash] entries. That is a frame perf could not resolve to a symbol. Each one is a real function that will appear in your flame graph as an unlabelled box, and a flame graph made mostly of [unknown] boxes is the most common disappointment in this entire subject.

kernel.perf_event_paranoid = 2
kernel.kptr_restrict = 0

 Performance counter stats for 'sleep 0.1':

              1.05 msec task-clock:u              #    0.010 CPUs utilized

       0.101815862 seconds time elapsed

       0.001388000 seconds user
       0.000000000 seconds sys

Error:
Access to performance monitoring and observability operations is limited.
Consider adjusting /proc/sys/kernel/perf_event_paranoid setting to open
access to performance monitoring and observability operations for processes
without CAP_PERFMON, CAP_SYS_PTRACE or CAP_SYS_ADMIN Linux capability.
More information can be found at 'Perf events and tool security' document:
https://www.kernel.org/doc/html/latest/admin-guide/perf-security.html
perf_event_paranoid setting is 2:
  -1: Allow use of (almost) all events by all users
      Ignore mlock limit after perf_event_mlock_kb without CAP_IPC_LOCK
>= 0: Disallow raw and ftrace function tracepoint access
>= 1: Disallow CPU event access
>= 2: Disallow kernel profiling
To make the adjusted perf_event_paranoid setting permanent preserve it
in /etc/sysctl.conf (e.g. kernel.perf_event_paranoid = <setting>)

What to read out of this.

Step 2 succeeds and step 3 fails, and the difference is one flag. At perf_event_paranoid = 2 an unprivileged user may profile their own process, so perf stat -- sleep 0.1 works. Add -a for system-wide and the kernel refuses, with exit status 255 — and, unusually for a Linux error, it prints the entire table of levels, and names CAP_PERFMON as the fix. That is the friendliest permission error in this whole track; read it rather than reaching for sudo.

Note the :u modifier on the event name in step 2. At level 2 an unprivileged user gets user-space events only, which is the same restriction that refuses -a. Run the identical command as root and the event is plain task-clock. If your two runs disagree, check which user produced which.

What to do about it, in order. For a one-off investigation, sudo perf … is fine. For a machine where developers profile routinely, set kernel.perf_event_paranoid = 1 (per-process for everyone, no system-wide) or 0, deliberately and fleet-wide. For a service that must profile itself, grant it CAP_PERFMON rather than root — that is precisely the capability that was carved out of CAP_SYS_ADMIN in Linux 5.8 so that observability tools would stop needing the junk drawer.

kptr_restrict = 0 is the modern default, but on its own it does not get you kernel symbols: /proc/kallsyms still hands 0000000000000000 to a process that has neither CAP_SYSLOG nor perf_event_paranoid <= 1. Verify with head -2 /proc/kallsyms as the user that will run perf — if the addresses are zeros, that is why your kernel frames are hex, and the knob to move is usually perf_event_paranoid, not kptr_restrict.

Step 4 is a heuristic, not a proof. A high count of push %rbp at function entry suggests frame pointers are present; a near-zero count on a large binary suggests they were omitted. The definitive answer is how the distribution built the package — Ubuntu 24.04 and Fedora 38 onwards mostly have them on 64-bit, except where they were deliberately left off, notably the Python interpreter.

And the third symbol-breaker is missing debug symbols: install the -dbgsym / -debuginfo package for the binary you are profiling, or you will get correct addresses with no names. For a managed runtime add a fourth — JIT-compiled frames, which need the runtime's perf-<pid>.map and therefore a restart.

perf is the kernel's own profiler, built on the perf_events subsystem. It works in two modes and I would use them in order.

Count first: perf stat adds up events over a run at almost no cost. The ratio I look at before anything else is CPU time versus elapsed time — CPUs utilized in its output. Near 1.0 per thread means CPU-bound and worth profiling; near zero means the process is blocked and a CPU profile would be an empty, truthful, useless picture.

Then sample: perf record -F 99 -a -g -- sleep 30 takes 99 stack samples per second per CPU. perf report --stdio --no-children is often the whole answer; the flame graph is for sharing it and for spotting shapes.

Read the flame graph correctly: width is the fraction of samples, the x-axis is not time, and you read top-down for cost and bottom-up for cause.

The details that separate candidates: knowing what breaks. Hardware events like cycles are usually <not supported> on a cloud VM because there is no virtual PMU, and perf silently falls back to task-clock — so run perf evlist on the profile before drawing conclusions. perf_event_paranoid defaults to 2 and blocks -a. Missing frame pointers give [unknown] frames, fixed with --call-graph dwarf at a real cost. And inside a container the blocker is usually seccomp, not capabilities, because Docker's default profile blocks perf_event_open.

Four causes, checked in this order.

Missing frame pointers — the compiler omitted them, so the stack cannot be walked cheaply. Confirm by re-recording with --call-graph dwarf; if the stacks appear, that was it. The long-term fix is building with -fno-omit-frame-pointer, which Fedora 38 and Ubuntu 24.04 now do by default on 64-bit — though Ubuntu deliberately excludes the Python interpreter, so "modern distro" is not a guarantee.

Missing debug symbols — install the -dbgsym or -debuginfo package. You get correct addresses and no names without it.

kptr_restrict non-zero, if it is specifically the kernel frames that are hex.

JIT-compiled code — the functions did not exist on disk, so there is nothing to look up. The JVM, Node and .NET can emit a /tmp/perf-<pid>.map, but only if started with the right flag, which means a restart.

The details that separate candidates: stating the trade-off of --call-graph dwarf rather than just recommending it. It copies a chunk of stack per sample — heavy enough to change the behaviour of what you are measuring, and it truncates at the configured stack size, so deep recursion still comes out wrong. lbr is cheap but shallow and unavailable on most cloud VMs. Frame pointers remain the only option that is cheap, deep and correct, which is why distributions went back to them after a decade.

Whenever the problem is waiting rather than computing — which, for a typical web service, is most of the time.

A CPU profile samples threads that are on CPU. A thread blocked on a disk read, a database round trip, a mutex, or a socket is not running, so it is never sampled and never appears. The graph you get is small, tidy and completely honest about the 3% of time that was spent computing.

The check that prevents the wasted afternoon is one number from perf stat: CPUs utilized. Near 1.0 per thread, profile the CPU. Near zero, the answer is off-CPU.

For off-CPU work the tools are different: /proc/<pid>/wchan and /proc/<pid>/stack for a stuck process, PSI for whether the stall is CPU, memory or I/O, and off-CPU flame graphs built from scheduler tracepoints (sched:sched_switch and sched:sched_stat_sleep) with perf or bpftrace — where the y-axis is blocked time rather than CPU time.

The details that separate candidates: naming the "off-CPU flame graph" as a specific technique rather than gesturing at eBPF, and noting that the two are complementary rather than alternatives — Gregg's own advice is to produce both and read them together, because a change that moves time from one to the other looks like an improvement in whichever one you happened to look at.

--- untraced ---
200000 bytes (200 kB, 195 KiB) copied, 0.0740487 s, 2.7 MB/s
real	0m0.076s
user	0m0.030s
sys	0m0.048s

--- strace -e trace=read ---
------ ----------- ----------- --------- --------- ----------------
100.00    1.656284           8    200001           read
------ ----------- ----------- --------- --------- ----------------
100.00    1.656284           8    200001           total
real	0m16.642s
user	0m1.375s
sys	0m14.268s

--- strace -e trace=openat (dd makes ~4 of these) ---
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         4           openat
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         4           total
real	0m12.579s
user	0m0.883s
sys	0m10.807s

--- strace --seccomp-bpf -e trace=openat ---
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         4           openat
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         4           total
real	0m0.075s
user	0m0.038s
sys	0m0.039s

What to read out of this. Four numbers: 0.076, 16.6, 12.6, 0.075 seconds.

0.076 → 16.6 seconds is a 219× slowdown. That is the headline, and it is why "just strace it" is not a production answer. On a service handling real traffic, a 200× slowdown is an outage you caused while investigating a slowdown.

Now the third number, which is the one that teaches the mechanism. Tracing openat — a call dd makes exactly four times — still cost 12.6 seconds. The filter reduced what was printed, not what was stopped. Every one of those 200,000 read calls still stopped the process twice so strace could look at it and decide it was not interesting. -e is a display filter, not a performance control, and almost nobody knows this until it bites them.

And the fourth number is the fix: 0.075 seconds — indistinguishable from untraced. --seccomp-bpf pushed the filtering into the kernel, so the process is only stopped for openat. Same output, same four calls recorded, the entire overhead gone.

Two conditions on that fix, and both are easy to miss. It does nothing without -f — drop the -f and the same command takes about 13 seconds again, which is the cheapest possible proof of the gotcha. And it is not applicable to -p / --attach at all, so it cannot rescue you on a process that is already running — which is precisely the production case.

Look at where the time went, too. In the traced runs sys is 14.3 and 10.8 seconds against roughly 1 second of user. The cost is almost entirely kernel time — context switching in and out of the tracer — which is exactly what the two-stops-per-syscall mechanism predicts.

What to use instead in production. perf trace is the buffered, ring-buffer equivalent built on perf_events. Published figures put strace anywhere from 173× (Arnaldo Carvalho de Melo, via PingCAP) to 442× (Gregg, dd bs=1 count=500k), and perf trace at about 1.36× on a dd workload — but those are separate experiments, not one head-to-head. An eBPF tracer is cheaper still. Measure it on your own hardware rather than trusting a ratio: on a small VM with a restricted PMU, perf trace can lose its advantage entirely.

And when strace is the right tool: a process that is already stuck and doing nothing, a short-lived command in development, or a one-shot strace -f -e trace=openat -o /tmp/log ./thing to answer "which config file is it actually reading?". Completeness on an idle process costs nothing.

733
alarmtimer
amd_cpu
avc
block
bpf_test_run
bpf_trace
bridge
capability

blk nop

# tracer: nop
#
# entries-in-buffer/entries-written: 5/5   #P:2
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
              ls-6932    [001] ..... 18743.713170: sched_process_exec: filename=/usr/bin/ls pid=6932 old_pid=6932
            date-6933    [001] ..... 18743.715089: sched_process_exec: filename=/usr/bin/date pid=6933 old_pid=6933
           sleep-6934    [000] ..... 18743.716902: sched_process_exec: filename=/usr/bin/sleep pid=6934 old_pid=6934

What to read out of this.

733 tracepoints are already compiled into this kernel, across dozens of subsystems, and every one of them was costing nothing until the moment you wrote a 1. That is the static-key point from D2, made concrete: the instrumentation is present and switched off, not absent.

available_tracers says blk nop — and that is a real finding, not an error. This kernel was built without CONFIG_FUNCTION_TRACER, so function and function_graph are simply not on the menu. Cloud and container-host kernels are often trimmed this way. Check available_tracers before planning an investigation around function tracing, because the tutorial you are following was written on a kernel that had it.

The trace output is the payoff, and it needed nothing installed. No perf, no bpftrace, no package manager, no network. Just a write to a file and a read from another. On a locked-down production host where you cannot install anything, this is frequently the only tracing you will get — which is exactly why it is worth knowing the paths by heart.

Read the columns. ls-30486 is command and PID, [001] is the CPU, the five dots are per-event flags (interrupts off, need-resched, hardirq/softirq context, preempt depth, migrate-disable), then a timestamp in seconds since boot, then the event and its fields. sched_process_exec fires on every exec, so this is a complete record of every program the machine started while it was enabled — the same data execsnoop reports, from a file.

Clear the buffer before you enable anything, which is why the exercise writes to trace first. Reading trace does not consume it, so a second run appends to whatever the first left behind — the commonest way to read someone else's trace and believe it is yours.

Remember to switch it off. A tracepoint left enabled keeps filling a ring buffer forever. It is bounded and it will not fill your disk, but it will quietly cost a little CPU and confuse the next person who reads trace.

It traces a process's system calls, using ptrace(2) — the debugger interface. That mechanism is the answer to both halves of the question: the kernel stops the process twice per system call, once on entry and once on return, so the tracer can read its state.

I use it for questions of the form "what is this program actually touching?" on something that is idle, stuck, or in development: which config file it opened, why it cannot find a library, what it did just before it hung. strace -f -e trace=openat -o /tmp/log ./thing answers those in seconds.

I do not attach it to a process serving live traffic. The slowdown is measured in hundreds of times, not percent.

The details that separate candidates: two. First, -e trace= is a display filter, not a performance control — the process is still stopped on every syscall so strace can decide whether to print it, so filtering does not buy you speed. Second, the fix: --seccomp-bpf installs a seccomp filter so the kernel only stops for the calls you asked for, which removes essentially all of the overhead — but it silently does nothing unless -f is also given. Finishing with the production alternatives (perf trace for the buffered version, bpftrace when you want a summary rather than a firehose) shows you have actually had to make this choice.

They differ in what they observe, how much they cost, and what they give you back.

strace observes system calls only, by stopping the process, and gives you a complete transcript. Complete, expensive, development-only.

perf does two different jobs. perf stat counts events with negligible overhead; perf record samples stacks at a chosen frequency and gives you a statistical picture — cheap because it is a sample, incomplete for the same reason. perf trace is its buffered strace equivalent.

eBPF (bpftrace, bcc) attaches to any of the four hook types and — the key property — aggregates in the kernel, so a histogram of a million events crosses into user space as one histogram, not a million lines. That is what makes it viable on a live production host.

The order I actually use them: perf stat to characterise, perf record if CPU-bound, bpftrace if I need a distribution or an off-CPU answer, strace only on something already broken and idle.

The details that separate candidates: saying that sampling and tracing answer different questions, not the same question at different prices. A profile tells you where time goes on average; it will never show you the one request in ten thousand that took four seconds. Tracing will, at a cost. And adding that eBPF's real constraint is neither speed nor safety but kernel version and probe stability — a tool built on tracepoints survives upgrades, one built on kprobes may silently stop matching anything.

Establish first whether it is spinning or blocked, because everything after that diverges. top or pidstat 1 for the process: near 100% CPU means spinning, near 0% means blocked, and the tools for the two share nothing.

If it is blocked, the state and the wait channel name the cause without any tool being installed: ps -o state,wchan:32 -p PID, and cat /proc/PID/stack for the kernel stack. D state points at disk or a network filesystem; S with a wait channel in a futex points at a lock. cat /proc/PID/status shows the signal masks (Module 04) and ls -l /proc/PID/fd shows what it has open — often the answer on its own, when the last fd is a socket to something that has gone away.

If it is spinning, profile it: perf record -F 99 -g -p PID -- sleep 10 and look at the top self-time symbol.

strace -p PID is safe here precisely because the process is doing nothing — there are no syscalls to slow down. If it is stuck in one call, strace will show it sitting there, which is a definitive answer.

The details that separate candidates: checking /proc/PID/stack at all — most people never look — and knowing to check whether the process is in the same cgroup as something being throttled (Module 12's nr_throttled), because a container at its CPU quota looks exactly like a slow process from the inside. Also mentioning SIGQUIT for a JVM, which dumps every thread stack to stdout and is often faster than any of the above.