Ramblings of an aging IT geek
← Ramblings of an aging IT geek
performance

perf top on a box that had no business being busy

An idle-looking server sitting at 40 percent CPU turned out to be burning all of it inside the kernel on logging, and perf top pointed straight at it in seconds.

A monitoring graph and a server rack

A box that should have been nearly idle was sitting at a steady 40 percent CPU. Low traffic, no scheduled jobs running, nothing in the application logs to suggest it was doing anything at all. top confirmed the number and then refused to be helpful about it: the CPU was there, the process was ours, but what it was spending those cycles on, top cannot tell you. It shows you that a thing is busy. It does not show you why.

This is exactly the gap perf top fills, and I reach for it far less often than I should. It samples the CPU and shows you, live, the functions where the time is actually going, kernel and userspace together. You run it, you watch for a few seconds, and the noise sorts itself into a list with the real culprit usually sat near the top.

perf top -g

In this case the top entries were not in our code at all. They were kernel symbols, and a lot of them were clustered around the write path and locking. That is a fingerprint. When an "idle" process is burning CPU inside the kernel on writes, it is almost always doing far more I/O than anyone thinks it is.

Following the smell

The pointer was clear enough that I went looking at what the process was writing, and strace -f -e trace=write on the pid told the rest of the story immediately. It was logging. Specifically, it was logging at debug level, flushing every line to disk synchronously, on a code path that ran in a tight loop. Someone had turned debug logging on during an incident weeks earlier, the incident had been resolved, and the logging had never gone back off. The service was spending nearly half a core formatting and fsyncing log lines that no human had read since the day they were turned on.

A close-up of the perf output with kernel symbols at the top

The shape of the problem is worth holding onto, because it generalises. Synchronous logging on a hot path is one of the great quiet CPU thieves. Each line is a syscall, often a lock, sometimes a flush, and individually each is cheap, but multiply by a loop running thousands of times a second and you have a server that looks haunted. It is busy doing real work; the work is just pointless.

The fix was two parts. Turn the log level back down to where it belonged, which dropped the box from 40 percent to single digits within seconds. Then make the logging asynchronous and buffered so that even at debug level it batches writes rather than fsyncing each line, so the next person who flips debug on during an incident does not quietly leave a tax running for a month.

The real takeaway is about the tool, though. top told me the box was busy. It could never have told me it was busy logging. perf top did, in about ten seconds, by sampling where the cycles genuinely went rather than which process owned them. If you have ever stared at a CPU graph that does not match any work you can account for, that ten-second sample is the thing to reach for before you start guessing.