A screen took 14 seconds with the server at 12% CPU: I measured the wait before approving two more instances

The complaint was specific. The operations dashboard took 14 seconds to open. The capacity panel next to it showed the four application instances running at a shade over 12% CPU, averaged over the week. Both numbers were true at the same time, and that pair is the whole story.

The meeting had already decided the shape of the answer: CPU is getting scarce, reservations are the hedge, put two more instances in the plan. LeadDev ran a piece called "Stop asking engineers how many machines they need", and The Pragmatic Engineer's Pulse recommended reserving compute ahead of the squeeze. Neither one tells you what your number should be. The number I was being asked to sign off on had nothing behind it except the latency people were angry about.

A box sitting at 12% has almost nothing to compute. It is waiting on something. So before touching instance counts I spent an afternoon finding out what it waits for.

Step 1: split the 14 seconds into app time and database time

No APM on this service, so the cheapest instrument was a middleware that logs total request time next to accumulated query time and query count.

app.use((req, res, next) => {
  const start = process.hrtime.bigint();
  req.dbMs = 0;
  req.queries = 0;
  res.on('finish', () => {
    const totalMs = Number(process.hrtime.bigint() - start) / 1e6;
    logger.info({
      route: req.route?.path,
      totalMs: Math.round(totalMs),
      dbMs: Math.round(req.dbMs),
      queries: req.queries,
    });
  });
  next();
});

The query wrapper adds to req.dbMs and increments req.queries. One page load, logged:

route=/dashboard totalMs=14102 dbMs=13140 queries=41

So 13.1 of the 14 seconds happened inside Postgres, spread over 41 round trips for a single screen. Application code was responsible for under a second. Adding instances multiplies the thing that was already idle.

Step 2: ask the database which statement owns the time

select
  calls,
  round((total_exec_time / 1000)::numeric, 1) as total_s,
  round(mean_exec_time::numeric, 1) as mean_ms,
  left(query, 52) as query
from pg_stat_statements
order by total_exec_time desc
limit 5;

 calls  | total_s | mean_ms | query
--------+---------+---------+------------------------------------------------------
  44412 |  8912.4 |   200.7 | select * from events where asset_id = $1 order by oc
    118 |  1204.8 | 10210.1 | select sum(amount) from ledger_entries where tenant_
   9031 |   301.2 |    33.4 | select id, name from assets where tenant_id = $1

The top row is 200 milliseconds per call, which nobody would flag in isolation. The damage is in calls. Thirty-seven of the 41 queries on that screen were that same statement with a different asset_id. An N+1 wearing a dashboard.

Step 3: EXPLAIN the cheap-looking query

EXPLAIN (ANALYZE, BUFFERS)
select * from events where asset_id = 90412 order by occurred_at desc limit 1;

 Limit  (cost=18402.01..18402.01 rows=1 width=48)
        (actual time=198.812..198.814 rows=1 loops=1)
   ->  Sort  (cost=18402.01..18402.02 rows=1 width=48)
         Sort Key: occurred_at DESC
         ->  Seq Scan on events  (cost=0.00..18402.00 rows=1 width=48)
                 (actual time=0.091..197.551 rows=1 loops=1)
               Filter: (asset_id = 90412)
               Rows Removed by Filter: 2148773
               Buffers: shared read=17894
 Planning Time: 0.214 ms
 Execution Time: 199.021 ms

No index on events.asset_id. Each call walked 2.1 million rows and read close to 18 thousand buffers off disk to return one row. Thirty-seven times per page.

Step 4: confirm it is I/O and not compute

select wait_event_type, wait_event, count(*)
from pg_stat_activity
where state = 'active'
group by 1, 2
order by 3 desc;

 wait_event_type |   wait_event    | count
-----------------+-----------------+-------
 IO              | DataFileRead    |    17
 Client          | ClientRead      |     4
 LWLock          | BufferMapping   |     2
                 |                 |     1

One backend running, seventeen blocked on reading data files. That is what 12% CPU looks like from the inside.

Three things I tried before that, and why they failed

• Connection pool from 20 to 60. The p95 went from around 14 seconds to about 19. More concurrent sequential scans competing for the same disk made it worse, not better.
• A 60 second cache on the dashboard payload. First load still 14 seconds, numbers looked stale to the people who watch them live, and the second screen using the same query shape stayed slow.
• One extra app instance in the load test. Latency moved inside the noise. Four application boxes were already queueing behind a single Postgres primary.

Any of the three would have survived the meeting. None moved the number anyone complained about.

The change that did

create index concurrently events_asset_id_occurred_at_idx
  on events (asset_id, occurred_at desc);

And then collapsing the 37 round trips into one statement:

select a.id, a.name, e.occurred_at, e.amount
from assets a
left join lateral (
  select occurred_at, amount
  from events
  where asset_id = a.id
  order by occurred_at desc
  limit 1
) e on true
where a.tenant_id = $1;

Same log line after deploy:

route=/dashboard totalMs=871 dbMs=604 queries=4

From 14 seconds to roughly 900 milliseconds, with no change to instance count. CPU on the app boxes rose to around 19%, which was the part I liked most: the machines finally had work to do instead of waiting on a disk.

What this does to the capacity question

Utilization answers a different question than the one on the ticket. Concurrency you need is arrival rate multiplied by service time, so service time is the term you can actually negotiate. With 13 seconds of database wait per request, the reservation I was asked to approve would have bought the same 14 second screen at a bigger invoice, and the missing index would still be there when the reserved capacity expired.

I am not arguing against reserving compute. Scarcity is real and committing early can be the right call. The input to that commitment should be measured service time per endpoint, not a number an engineer feels pressured to say out loud in a planning meeting. Four numbers made the decision here, and all four are a day of work: request time split into app and database, calls ranked by total execution time, one EXPLAIN with BUFFERS, one snapshot of wait events.

How do you size a reservation when service time is still moving? I would like to know whether you gate instance requests behind a latency breakdown, or reserve first and tune after the invoice lands.