Part III · Chapter 3 · Under Load · lesson 2
CPU is at 40% and it is still slow
13 min
Builds on It runs fine on your laptop and badly in production
Part III · Chapter 3 · Under Load · lesson 2
13 min
Builds on It runs fine on your laptop and badly in production
Peak traffic quadrupled over six months. The p99 went from 40 milliseconds to 2.4 seconds. Every CPU graph on every instance reads 40%, memory is flat, and the disk is bored. Somebody has already said "it must be the database", and the database's own CPU graph also reads 40%.
Four readings separate the four candidates. None of them is a profiler, and all four take under a minute.
Predict
A request inside your service holds things. It holds a worker slot for its whole life. It holds a connection from a pool while it talks to the database. It holds one or more file descriptors for every socket it has open. And it holds all of those while it waits for the slowest thing it is waiting on.
That last clause is the mechanism. The processor is released the moment a request blocks on a socket; everything else it was holding is not. So a service whose requests spend most of their time waiting can exhaust every slot it has while leaving the CPU almost untouched.
Four pools, in the order they usually bite: database connections, file descriptors, worker or thread slots, and the capacity of whatever is on the other end.
One — connection pool waiters. The pool is the smallest of the four and the one most often sized by guesswork. If you run pgbouncer, its admin console answers directly:
psql -p 6432 -U pgbouncer pgbouncer -c 'SHOW POOLS;'
The column that matters is cl_waiting: clients that have asked for a server
connection and have not been given one. Anything other than zero at steady
state means every request is paying a queueing delay before it reaches the
database. Without pgbouncer, ask the database:
psql -c "SELECT state, count(*) FROM pg_stat_activity GROUP BY state;"
active close to max_connections means the server side is full. A pile in
idle in transaction means your application is holding connections across
something that is not a query — usually an HTTP call made inside a transaction,
which is the single most common version of this bug. If you are on the JVM with
HikariCP, the Micrometer gauge hikaricp_connections_pending is the same number
without the shell.
Two — file descriptors and sockets. Every socket is a descriptor, and the limit is per process and usually lower than people assume:
ss -s
ls /proc/$(pgrep -f 'gunicorn: master' | head -1)/fd | wc -l
grep 'Max open files' /proc/$(pgrep -f 'gunicorn: master' | head -1)/limits
ss -s gives you the socket totals by state in one line. Two patterns matter:
a count close to the descriptor limit, and a large timewait figure. The second
one is ephemeral port exhaustion rather than descriptor exhaustion, and it has a
different fix:
ss -tan state time-wait | wc -l
cat /proc/sys/net/ipv4/ip_local_port_range
If those two numbers are within sight of each other, the service cannot open new
outbound connections and new requests are failing at connect(). The fix is
connection reuse — keep-alive on the client, a pool rather than a fresh socket
per call — not a wider port range.
Three — worker and thread slots. The question is not how many workers you
have, it is what they are all doing. For Python, py-spy answers it without
restarting anything:
py-spy dump --pid $(pgrep -f 'gunicorn: worker' | head -1)
If every thread in every worker shows the same stack, blocked in a socket read
to the same host, your worker slots are the constraint and the thing on the
other end is the cause. On the JVM the equivalent is jcmd <pid> Thread.print
and counting frames; on Node there are no worker slots to exhaust, so the
analogue is event-loop lag, which perf_hooks.monitorEventLoopDelay() reports
directly. Gunicorn's own count of busy workers is the cheapest version of this
reading if you already export it.
Four — the downstream wait. This is where a trace earns its cost. In an OpenTelemetry waterfall you are looking for one specific shape: a span whose own duration is most of its parent's, with no child spans under it. That is time spent waiting on something not instrumented, which is almost always a network call or a lock.
Without tracing, one request measured by hand gets you most of the way:
curl -s -o /dev/null -w 'connect=%{time_connect} ttfb=%{time_starttransfer} total=%{time_total}\n' \
https://orders.internal/health
A large gap between connect and ttfb is the dependency thinking. A large
connect is the dependency's own accept queue being full, which is its version
of the same problem.
What would you do
A Python order service: twelve pods, gunicorn with eight sync workers each. It talks to one Postgres primary through pgbouncer, to an internal auth service over HTTP, and to Redis. Peak is four times what it was in April.
CPU 40% on the pods and 40% on the database. p99 2.4 seconds against a budget of 200 milliseconds. No deploy in nine days. You have shell access to a pod and to the pgbouncer host, tracing is not installed, and the incident channel wants an answer before the next standup.
Export four numbers permanently, because all four of the commands above are things you should not have to run during an incident:
SHOW POOLS or HikariCP's pending gauge.Those four plus request rate will diagnose most of this track without a trace. Tracing is still worth installing and it answers the question the four numbers cannot: which call inside the request is holding everything, which is reading four above.
Check
All of the above assumes the work is blocked rather than running. The test is
the one in the first reading set: if py-spy dump shows workers executing
application code rather than waiting in a socket read, and the flame graph has a
tall narrow tower in it, then the service is CPU-bound and this whole lesson is
the wrong lesson.
In that case the profile is the evidence, the fix is in the code or the algorithm, and utilisation genuinely is the measurement you want. The reason to check the four pools first is not that CPU is never the answer — it is that the four readings take one minute each and the profile takes an afternoon to act on.