The Load Was 117 and the CPUs Were Idle

The alert said load average 12.48 on a 16-core box, with a spike to 117.92 in the sar history. The obvious reading is that something is eating the CPUs.

The CPUs were 81% idle. They had been idle the whole time.

This is a walk through how that server was diagnosed, because the reasoning generalises: load average on Linux is not a measure of CPU demand, and treating it as one sends you looking in the wrong place for hours.

Step 1: is anything actually running?

Before touching anything, ask the load average to break itself down. The fourth field of /proc/loadavg is runnable / total processes.

$ nproc
16

$ cat /proc/loadavg
10.76 10.42 10.74 4/604 26423
                   ^
                   4 runnable, out of 604 processes

Load 10.76, and four tasks runnable. If this were CPU pressure that number would be somewhere near the load. It isn't, so the other ~7 are blocked on something. On a server, "something" is nearly always I/O.

That one command reframes the whole investigation. Everything after it is confirming the disk and finding out why.

Step 2: rule out CPU and memory properly

A hypothesis is worth little until the alternatives are dead. Both take one command.

              CPU     %user     %nice   %system   %iowait    %steal     %idle
11:00:01 AM   all      6.22      0.00      1.49     11.25      0.00     81.03
11:10:01 AM   all      3.82      0.00      0.92     11.87      0.00     83.40
11:20:01 AM   all      6.79      0.00      1.69      9.99      0.00     81.54
Average:      all      5.61      0.00      1.37     11.04      0.00     81.99

82% idle on average, and — importantly — %steal is 0. On a VM, steal time is the hypervisor giving your cycles to another guest. Zero steal rules out CPU contention on the host, which is the other explanation people reach for.

Memory next. The temptation is to look at "used" and panic:

              total        used        free      shared  buff/cache   available
Mem:          48136       35110        1246        2439       11779       10125
Swap:         16127         100       16027

           pswpin/s  pswpout/s
11:00:01 AM    0.00       0.00
11:10:01 AM    0.00       0.00
11:20:01 AM    0.00       0.00

97% "used" looks alarming and means nothing here. Most of it is a 24 GB database buffer pool plus page cache, which is exactly what you want RAM doing. The figure that matters is swap activity, and it is flat zero. Nothing is being paged. Memory is not the constraint.

Step 3: the disk, and the arithmetic that proves it

Now the actual cause. This is the part worth internalising, because the numbers prove the conclusion rather than suggesting it.

        DEV      tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz    await   svctm   %util
Average: sda   141.17      0.03   1905.16     13.50    150.64  1067.07    6.95   98.05
Average: sdb    21.87      0.00   1182.65     54.08      1.45    66.36   16.19   35.41
Average: vg-root  1.19     0.03     23.52     19.76      3.60  3018.82  817.46   97.41
Average: vg-home 140.71    0.00   1920.48     13.65    148.76  1057.27    6.97   98.02

Three calculations turn that table into a verdict.

1. The device's ceiling

svctm is how long the device takes to service one request: 6.95 ms. So the most it can ever do is:

1 / 0.00695 s = ~144 requests per second

Observed tps is 141. The application is asking for 98% of everything the device can deliver. At that utilisation, queueing theory says latency stops being linear and starts climbing a wall.

2. The queue is real, not an artefact

Little's law says queue length equals arrival rate times time in system. Check it against the reported queue depth:

tps 141 x await 1.067 s = 150.4     vs.  avgqu-sz 150.64

They agree to three significant figures. There genuinely are ~150 requests sitting in a queue whose configured depth is 128 — the queue is permanently over-full. Each request takes 7 ms to service and 1,067 ms to complete. Virtually all of that is waiting.

3. It's request count, not throughput

avgrq-sz 13.5 sectors x 512 bytes = 6.75 KB per request
141 tps x 6.75 KB = under 1 MB/s

Under a megabyte per second. If you were watching a bandwidth graph you would see nothing at all. Small random writes exhaust a device by request count long before they trouble its throughput, and this workload is entirely writes — rd_sec/s is ~0 on every device, because the working set is fully cached in RAM.

Step 4: ask the blocked processes what they're waiting for

ps can print wchan — the kernel function a sleeping process is parked in. For D-state processes this names the exact thing they're blocked on.

$ ps -eo state,pid,wchan:24,etimes,user,args | awk '$1 ~ /^D/'

D   786 flush_work              6132315 root    [xfsaild/dm-2]
D  3465 get_request               30377 root    [kworker/u32:3]
D 17434 xlog_state_get_iclog_spa  11069 root    [kworker/11:2]
D 17987 call_rwsem_down_write_fa   2603 postfix pickup -l -t unix -u
D 25245 blkdev_issue_flush          706 postfix bounce -z -t unix -u
D 28477 xfs_log_force_lsn            21 appuser postdrop -r

Two entries in that list are worth stopping on.

• xfsaild with etimes 6,132,315. That is elapsed seconds — 71 days, matching the machine's entire uptime. The XFS log flusher for that filesystem has been blocked continuously since boot. It has never once caught up.
• get_request. The kernel ran out of free slots in the block device request queue. Not slow — full.

And the kernel had been saying so all along:

[Mon Jun 29 17:58:06] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Mon Jun 29 18:06:06] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Mon Jun 29 18:30:06] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

Those start hours after the last boot. This was never an incident — it is a chronic condition that finally crossed an alert threshold.

Step 5: the spike that wasn't a spike

Load 117.92 at 11:10 still needs explaining. The instinct is to hunt for what launched. Compare the run queue against the process list instead:

          runq-sz  plist-sz  ldavg-1  ldavg-5  ldavg-15  blocked
11:00:01       47       708    10.17    10.45     10.65        3
11:10:01       29       896   117.92    60.82     30.66        3
11:20:01       32       682    10.43    17.08     21.35        3

Process count rose by 188 while the run queue actually fell, from 47 to 29. Those 188 processes were not running. Now work out whether 188 is even unusual:

$ grep ^processes /proc/stat
processes 22712416

22,712,416 forks / 6,132,120 s uptime = 3.7 forks/s = ~222 per minute

The server normally creates about 222 processes a minute. The "spike" of 188 is less than one minute of ordinary process creation. Nothing unusual started. The usual per-minute jobs started, couldn't complete because they were stuck on disk, and piled up. The load average measured the pile.

Step 6: why it parks at 10 instead of oscillating

A saturated disk alone would produce a load that rises and falls with demand. This one sat at ~10 indefinitely, because the symptom feeds the cause:

1. Disk latency is high, so a per-minute cron job takes longer than a minute
2. The next copy starts before the previous finishes, so concurrency rises
3. More concurrent jobs issue more I/O
4. More I/O means higher latency — back to step 1

The system finds an equilibrium where jobs overlap just enough to keep the disk pinned. That is why load parks at a number rather than spiking and recovering, and it is why flock on overlapping cron jobs is a real mitigation rather than housekeeping.

Step 7: knowing when you've hit a wall you don't own

Every knob inside the guest was already correct — which is itself a finding worth reporting, because it stops anyone else re-treading it:

~144 IOPS at 6.75 KB requests is mechanical-disk performance, or a throttled and contended shared volume. A flat ceiling with svctm pinned at 6.95 ms in every single sample is also exactly what a configured per-VM IOPS limit looks like.

Either way: no change inside the guest can raise it. The honest deliverable at that point is demand-side mitigation, plus the numbers the platform team needs to make the capacity case — the svctm, tps and avgqu-sz figures argue it better than any prose.

What turns up on the way

Investigations like this always surface unrelated problems. Two worth the mention:

$ grep -aoP '^Subject: \K.*' /var/spool/mail/appuser | sort | uniq -c | sort -rn | head -3
  43734 Cron  /usr/bin/rsync -a ...
   1584 Cron  /usr/bin/php .../backup.php 2>&1 >> .../backup.log

43,734 ÷ 1,440 runs per day = 30.4 days. A sync job had failed every single minute for a month. rsync -a is silent on success, so every one of those messages is a failure, and nobody was reading that mailbox.

The second line is a redirect ordering bug: 2>&1 >> file points stderr at the current stdout (the terminal, or in cron, mail) and only then redirects stdout to the file. Errors never reach the log they were meant for. It has to be >> file 2>&1. The order looks interchangeable and isn't.

The method, stripped down

1. Split the load average — /proc/loadavg field 4. Runnable, or blocked?
2. Kill the alternatives — %idle and %steal for CPU, pswpin/s for memory. Not "used", swap activity.
3. Do the arithmetic — 1/svctm is the ceiling. Compare to tps. Check avgqu-sz against Little's law.
4. Ask the blocked processes — wchan names the exact kernel path.
5. Check whether the spike is real — compare the process delta against the baseline fork rate before assuming something launched.
6. Know when the ceiling isn't yours — and hand over numbers, not adjectives.

None of that requires clever tooling. It is sar, ps, /proc and arithmetic. What it requires is not accepting "the load is high" as a description of the problem — because on Linux, a load of 117 with idle CPUs isn't a busy server. It's a queue.