Slow APIs and database bottlenecks

The most common production complaint about a backend is not that it is down. It is that it is slow — p99 latency up, a timeout here and there, a page that takes four seconds on a bad day. And in most Java services, when an API is slow and the service's own CPU is not busy, the time is being spent waiting: for a query, for a lock, or for a connection to run the query on.

Those three look alike from the outside and have completely different fixes. This lesson shows each one on a real PostgreSQL 16 instance, with a table of two million orders, and the evidence that tells them apart.

#Latency up, CPU flat

The first thing to establish is where the time goes. If the service's CPU is high, the time is spent in your code, and the diagnosing lesson's thread-dump method applies. If the service's CPU is low and latency is high, the service is waiting on something — and for most services, the database is the first thing to check.

A distributed trace answers "where" directly: a request span of 800 ms with a 780 ms database span inside it is not ambiguous. Without traces, compare the API's latency graph with the database's query latency and the connection pool's metrics — hikaricp.connections.active, hikaricp.connections.pending, and hikaricp.connections.acquire in a Spring Boot service.

#Suspect one: the slow query

An endpoint shows a customer's recent orders:

SELECT id, status, total_cents FROM orders
WHERE customer_id = $1 ORDER BY created_at DESC LIMIT 20

On its own, it seems fine. Thirty calls from one client:

30 calls of the "recent orders" endpoint query, no index: p50 27 ms, max 278 ms

27 ms is nobody's idea of a crisis. Now the same query from 16 concurrent callers, which is a quiet afternoon for a real service:

no index: 16 concurrent callers × 10 queries: p50 217.8 ms, p99 558.6 ms, 62 queries/s

The median went from 27 ms to 218 ms, with no change to the query. Every call scans the table, and sixteen scans compete for the same CPU and the same memory. A query that is merely slow alone becomes the bottleneck under concurrency — which is why it passed every test and failed in production.

Finding it. pg_stat_statements records every normalised query with its call count and total time. Sorted by total time, not mean, because the query that costs the most overall is the one worth fixing first:

│ calls │ total_ms │ mean_ms │ query                                                                    │
│ '30'  │ 1146     │ '38.2'  │ 'SELECT id, status, total_cents FROM orders WHERE customer_id = $1 ORDE' │
│ '1'   │ 0        │ '0.1'   │ 'SELECT $1 FROM orders WHERE id = $2'                                    │

Understanding it. EXPLAIN (ANALYZE, BUFFERS) runs the query and shows what actually happened:

Limit (actual time=24.228..26.945 rows=12 loops=1)
  ->  Gather Merge (actual time=24.227..26.943 rows=12 loops=1)
        Workers Planned: 2
        ->  Sort (actual time=22.860..22.860 rows=4 loops=3)
              Sort Key: created_at DESC
              ->  Parallel Seq Scan on orders (actual time=4.561..22.790 rows=4 loops=3)
                    Filter: (customer_id = 1041)
                    Rows Removed by Filter: 666663
                    Buffers: shared hit=16227 read=815 written=70
Execution Time: 26.973 ms

Read it from the bottom up. A sequential scan, on three processes, read about 17,000 pages and threw away two million rows (666663 removed per loop, three loops) to find twelve. That ratio — rows examined against rows returned — is the signature of a missing index.

Fixing it safely. An index on the filter column, with the sort column after it:

CREATE INDEX CONCURRENTLY orders_customer_recent ON orders (customer_id, created_at DESC)
--- took 1.8 s

CONCURRENTLY matters in production: a plain CREATE INDEX blocks writes to the table for as long as it runs, which on a large table is a self-inflicted outage. The concurrent form is slower and cannot run inside a transaction, and it does not block writes. After:

->  Bitmap Index Scan on orders_customer_recent (actual time=0.031..0.031 rows=12 loops=1)
      Index Cond: (customer_id = 1041)
      Buffers: shared hit=3
Execution Time: 0.301 ms

with the index: 16 concurrent callers × 10 queries: p50 1.6 ms, p99 61.8 ms, 1988 queries/s

From 62 queries a second to about 2,000, and a p50 from 218 ms to 1.6 ms. The p99 of 62 ms in that run most likely comes from each caller's first query, which also had to open a new connection; the lab did not separate the two, so treat that tail with caution.

#Suspect two: the lock wait

The second suspect produces no slow query at all. A refund job opens a transaction, locks an order row with SELECT … FOR UPDATE, and then does something slow before committing. Meanwhile the API tries to update the same order.

While the API request hangs, pg_stat_activity shows exactly what is going on:

│ pid │ app          │ state                 │ wait_type │ wait_event      │ blocked_by │ xact_age_s │ query                                              │
│ 362 │ 'refund-job' │ 'idle in transaction' │ 'Client'  │ 'ClientRead'    │ []         │ '0.5'      │ 'SELECT * FROM orders WHERE id = 1041 FOR UPDATE'  │
│ 363 │ 'orders-api' │ 'active'              │ 'Lock'    │ 'transactionid' │ [ 362 ]    │ '0.5'      │ "UPDATE orders SET status = 'PAID' WHERE id = 104" │

orders-api UPDATE finished after 3.03 s

Three columns carry the diagnosis:

• The API's session is active, but its wait type is Lock — it is not executing, it is queued.
• pg_blocking_pids names the session blocking it: 362.
• Session 362 is idle in transaction: it holds a lock and is doing nothing in the database. The slow work is happening in the application, with a transaction open.

The UPDATE itself takes microseconds. It waited three seconds for someone else's transaction. pg_stat_statements would record it as slow, and no index would help.

Set idle_in_transaction_session_timeout so a forgotten transaction is ended by the database, and alert on the age of the oldest open transaction.

#Suspect three: the empty pool

The third suspect happens before the query reaches the database. A service's connection pool has a fixed size. If every connection is busy, the next request waits for a connection — and if none is freed in time, it fails.

A pool of five connections. Five slow queries — pg_sleep(3), standing in for a report or a lock wait — take all of them. Then ten ordinary one-millisecond queries arrive:

pool of 5: total 5, idle 0, waiting 0
10 one-millisecond queries: 0 succeeded, 10 failed after 1.00 s: timeout exceeded when trying to connect

Every fast query failed, and none of them reached the database. From the database's side, nothing is wrong: five sessions are running, and the ten failed requests never appear in pg_stat_activity or pg_stat_statements. The evidence lives only in the application — pool metrics, and the error message about acquiring a connection. (This lab used Node's pg pool, whose timeout message is quoted above; HikariCP's equivalent is Connection is not available, request timed out after 1000ms.)

Pool exhaustion is usually a symptom of one of the other two suspects: slow queries or lock waits hold connections longer, and the pool runs dry. The fix is to find what is holding connections, not to enlarge the pool — a bigger pool lets more queries compete for the same database CPU and makes the first suspect worse. The connection pooling lesson in the relational databases course covers sizing.

#Telling them apart

#Fixing safely under pressure

• Kill the blocker, not the victims. pg_terminate_backend(362) ends the transaction holding the lock; cancelling the waiting queries only adds retries.
• Indexes: CONCURRENTLY, always, on any table that takes writes, and check afterwards that the index is valid — a failed concurrent build leaves an invalid index behind.
• Timeouts at every layer: a statement timeout on the database role used by the API, a connection-acquire timeout in the pool, a request timeout at the edge. A request that waits forever holds everything it touched.
• Verify with the same evidence you diagnosed with: the query's total time in pg_stat_statements falls, lock waits disappear from pg_stat_activity, pending connections return to zero.