Slow website, idle server: finding where the time goes

Why the database is the usual suspect

When a page slows down, the database is where the symptom becomes visible first. Connections pile up, the process list fills with queries in the sending data state, and the slow query log starts growing. All of that is real, and none of it says where the time went. The database sits at the end of most request paths. A page that calls it two hundred times instead of twice, a worker that holds a connection open while it waits on a payment gateway, a cache that is being bypassed on every hit: each of these shows up as database load, because the database is doing exactly what it is asked, more often than it should be asked.

The same applies to the server. A box at high load is a box being given work. Whether the work is necessary is a question the load graph cannot answer.

Trace one request, not the whole site

The method is to pick one slow URL and follow it through the tiers, measuring at each boundary. Start from outside, from a machine that is not on the same network, and let curl report where the time goes before the first byte arrives.

$ curl -o /dev/null -s -w 'dns %{time_namelookup}  connect %{time_connect}  tls %{time_appconnect}  ttfb %{time_starttransfer}  total %{time_total}\n' https://www.example.com/slow-page

If the time to first byte is most of the total, the wait is on the server side. If the total is far larger than the time to first byte, the page is heavy or the path between the visitor and the edge is the story, and the server was not part of the wait.

On the box, sample the CPU while the slow request is in flight, not an idle hour later.

$ mpstat -P ALL 1 5
$ vmstat 1 5

A server that is mostly idle during a slow request, with no iowait and no steal, has cleared itself. The time is being spent waiting on something, not computing.

Then the application. Most frameworks can log, per request, the number of queries issued, the total time spent in them, and the time spent in outbound HTTP calls. Turn that on for the slow URL. Two numbers settle the argument: how many queries one page issues, and how much of the wall-clock time was spent outside the application entirely.

Finally the database, with the slow query log on and the threshold low enough to catch what matters.

SET GLOBAL slow_query_log = ON;
SET GLOBAL long_query_time = 0.2;
SET GLOBAL log_queries_not_using_indexes = ON;

Read the log for the window of the slow request. A handful of queries that each take seconds is a database problem. Thousands of queries that each take a millisecond is an application problem the database is being blamed for.

The patterns that measure out

With the tiers separated, the cause tends to take one of a few shapes.

An endpoint called in a loop. A front end that re-fetches the same resource on every state change, or a page that issues one query per row instead of one query per page. The database answers each call quickly; the count is the problem.

A synchronous call to someone else. A payment provider, an ERP, a shipping API, a tag manager, sitting in the request path behind a long timeout. The server is idle for the whole wait, and the page is as slow as the slowest third party it depends on.

A cache that is being defeated. Headers that forbid caching on pages that do not change, or no edge cache in front of anonymous traffic that was never dynamic.

Pools sized by guesswork. Worker, connection and buffer pools set too large as often as too small. A pool far larger than the machine can serve concurrently turns a queue into a thrash.

Real exhaustion is the last shape, and when it appears it is usually downstream of one of the first three. The machine running out of something is the end of the story, not the beginning.

What a bigger server changes

Adding cores or memory shortens the part of the request that was computing. If that part was already small, the page does not get faster; the wait moves with it. The loop still loops, the third party still takes its time, the cache is still bypassed. The upgrade also hides the measurement that would have found the cause, because the graph that was red is now amber, and the ticket closes.

This is why we trace before we quote. A healthy platform stays boring, and the work is to find the tier that owns the time, even when that tier sits above anything we operate, and to hand back the measurement that points at the line.