Everything slow, CPU idle, iowait at 60%: tracing disk saturation to a log compressor

Every weekday between about 00:05 and 00:40 UTC, the internal reporting service, a PHP application with a MySQL database on the same VM, became almost unusable. Pages that normally loaded in 300 ms took eight to twelve seconds. By the time anyone in the Europe office looked, it was fine again.

The CPU graph was the confusing part: it showed the machine mostly idle during the slow period.

Catching it live

We scheduled a session for the next night and ran the basics at 00:10:

vmstat -w 1 5

procs -----------memory---------- ---swap-- -----io---- -system-- --------cpu--------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 1 22      0 402112  20412 6120380   0    0 61240  1802 2210 3104  8  5 26 61  0
 0 24      0 398220  20412 6121004   0    0 62874  1690 2180 3011  7  6 25 62  0

Twenty-plus processes blocked (b), 61% iowait (wa), heavy reads (bi about 61 MB/s) and few runnable tasks. The CPU was idle because everything was waiting for the disk.

cat /proc/pressure/io
# some avg10=78.21 avg60=74.90 avg300=40.12
# full avg10=55.30 avg60=52.07 avg300=27.88

PSI confirmed it: more than half the time, all active tasks were stalled on I/O.

Which device?

iostat -xz 1 3

Device   r/s     rkB/s   r_await  w/s    wkB/s  w_await  aqu-sz  %util
nvme1n1  480.0   61440.0   46.10  38.0  1720.0    52.40   24.10  100.00
nvme0n1    1.0      12.0    0.40   4.0    60.0     0.90    0.01    0.80

nvme1n1 was the data volume holding both /var/lib/mysql and /var/log. Read latency of 46 ms and a queue of 24 requests on a cloud SSD meant it was at its limit. The volume was a 500 GB gp3 with default performance: 3,000 IOPS and 125 MB/s. We were reading at about 61 MB/s with relatively large requests, plus the database's random reads.

Which process?

sudo pidstat -d 1 5

UID   PID    kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
  0   18822  58120.00      0.00      0.00     489  gzip
999    1311   2840.00   1612.00      0.00      91  mysqld

iotop -oPa showed the same: a gzip process reading almost all the bandwidth. Its parent:

ps -o pid,ppid,cmd -p 18822; ps -o pid,cmd -p $(ps -o ppid= -p 18822)

  PID  PPID CMD
18822 18790 /bin/gzip
18790 /usr/sbin/logrotate /etc/logrotate.conf

What we ruled out

• Slow queries. The MySQL slow log during the window showed ordinary queries taking long, not new heavy queries. They were slow because their reads waited behind the compressor.
• Backups. The database backup ran at 02:00 and finished in 20 minutes.
• Burst credit exhaustion. gp3 volumes do not use burst credits; their baseline is fixed, so the limit was the provisioned throughput, not a depleted balance.

Root cause

The daily logrotate run, triggered by the systemd timer just after midnight, compressed the previous day's application log. A verbose debug flag had been left on in production weeks earlier, so the log had grown to about 40 GB a day. gzip read it sequentially at full speed from the same volume as the database, consuming most of the volume's throughput limit. MySQL's random reads queued behind it.

Why CPU looks idle when the disk is the problem

iowait is CPU time spent idle while at least one task is waiting for I/O. It is not CPU being used. When the bottleneck is storage, processes sleep in uninterruptible state (D), the run queue is short and the CPU graph looks healthy. Load average, which on Linux counts tasks in D state, rises; that is why load can be high while CPU usage is low.

Cloud volume limits

Cloud block storage has two limits that both matter: IOPS and throughput. A single sequential reader with large requests can hit the throughput limit while using few IOPS, and once the volume is at its limit, every other request waits, regardless of who issued it. Linux I/O schedulers on NVMe devices (often none) do little to protect latency-sensitive readers from a bulk reader.

Environment

Step 1: stop the excess logging

The biggest win was turning the log level back to info. The daily log dropped from 40 GB to 900 MB. That alone reduced compression to under a minute.

Step 2: separate logs from the database volume

We created a second, smaller gp3 volume for /var/log and moved the logs there. Bulk log work can no longer compete with the database for the same throughput limit. In the cloud this is cheap; on physical servers, the same idea means separate disks or at least separate partitions with their own limits.

Step 3: run compression at low I/O priority

logrotate does not have its own priority setting, but the systemd service that runs it can:

# systemctl edit logrotate.service
[Service]
Nice=19
IOSchedulingClass=idle
CPUSchedulingPolicy=idle

With the idle I/O class, the kernel serves compression I/O only when nothing else wants the disk. On schedulers that support I/O priorities (BFQ, and to a degree mq-deadline) this works well; with the none scheduler on NVMe it has little effect, so we also capped the service's bandwidth through the cgroup:

[Service]
IOReadBandwidthMax=/dev/nvme1n1 20M
IOWriteBandwidthMax=/dev/nvme1n1 20M

Step 4: compress with less work

/var/log/reporting/*.log {
    daily
    rotate 14
    compress
    delaycompress
    compresscmd /usr/bin/zstd
    compressext .zst
    compressoptions -3
    uncompresscmd /usr/bin/unzstd
    missingok
    notifempty
    copytruncate
}

zstd at level 3 compresses faster than gzip at a similar ratio, and delaycompress leaves yesterday's file uncompressed until the next run, spreading the work.

Alternatives and trade-offs

• Ship logs off the host to a log platform and keep only a short local buffer. The best long-term answer, and what we did later.
• Raise the volume's throughput. gp3 throughput can be increased independently of size. It helps, but it pays for the waste instead of removing it.

How to test the fix

Force a rotation on a staging copy with a large file and watch latency:

fallocate -l 20G /var/log/reporting/app.log
sudo systemctl start logrotate.service &
iostat -xz 1 | grep nvme1n1

Confirming in production

The next night, iostat during rotation showed under 5 MB/s on the database volume and normal r_await. Page latency for the reporting app stayed at its usual 250-350 ms through midnight, and PSI io full stayed below 2%.

Regression guard

• An alert on node_pressure_io_stalled_seconds_total rate above 0.3 for five minutes.
• An alert when the application log grows faster than 5 GB per day, which catches forgotten debug flags.
• Volume layout (separate log volume) is part of the server template.

Security implications

Debug logging in production often contains request bodies, tokens and personal data; that was true here and was a bigger issue than the performance. The logs were reviewed, the sensitive fields were added to the logger's redaction list, and the old 40 GB files were deleted after the retention check. Disk saturation is also a denial of service vector; isolating logs protects the database from it.

Prevention checklist

• When CPU is idle but things are slow, look at wa, b and PSI before anything else.
• Keep logs and databases on separate volumes or devices.
• Run housekeeping jobs with low I/O priority and bandwidth caps.
• Alert on log growth rate, not just disk space.
• Never leave debug logging enabled in production without an expiry.

References

• Linux kernel documentation, PSI: https://docs.kernel.org/accounting/psi.html
• iostat manual: https://man7.org/linux/man-pages/man1/iostat.1.html
• systemd.resource-control, IO bandwidth limits: https://www.freedesktop.org/software/systemd/man/latest/systemd.resource-control.html
• Amazon EBS volume types, gp3: https://docs.aws.amazon.com/ebs/latest/userguide/general-purpose.html
• logrotate manual: https://man7.org/linux/man-pages/man8/logrotate.8.html