ObservabilityoptimizationBeginner

The order page spends 140 ms in the database — in 38 pieces

Symptoms

  • GET /orders/:id p50 is 210 ms and p99 600 ms; the order team’s explanation is "the database is slow".
  • The slow-query log is empty: no query takes more than 3 ms.
  • Database CPU is 18%; the DBA sees nothing wrong.
  • Connection-pool wait time in order-svc rises with request rate even though the database is idle.
trace 4b1e9d…   GET /orders/8841                                   232 ms
├─ api-gateway                                                         6 ms
└─ order-svc   GET /orders/8841                                      221 ms
   ├─ db  SELECT * FROM orders WHERE id = $1                           2.1 ms
   ├─ db  SELECT * FROM order_items WHERE order_id = $1                2.4 ms   (37 rows)
   ├─ http  GET catalog-svc/products/1021                              4.9 ms  ┐
   │   └─ db  SELECT * FROM products WHERE id = $1                     1.8 ms  │
   ├─ http  GET catalog-svc/products/1044                              4.7 ms  │  × 37, one after another
   │   └─ db  SELECT * FROM products WHERE id = $1                     1.7 ms  │  (37 × ~4.8 ms ≈ 178 ms wall time)
   ├─ …                                                                        ┘
   └─ render                                                           8 ms

spans in trace: 78 · db spans: 39 · sum of db span time: 140 ms · longest db span: 2.4 ms
# order-svc/orders.ts
for (const item of items) item.product = await catalog.getProduct(item.productId)

Investigate

Inspect areas in any order (0/7 inspected). When you think you know the root cause, commit to it.

Database CPU and slow-query log
Index on products
Connection pool
The loop in order-svc
catalog-svc’s API
Network latency between services
Recent deploys