Your ORM issued 400 queries and the p99 looked fine until it didn't

An endpoint that returns a customer’s order history starts timing out. Nothing about it changed. The query plan is unchanged, the indexes are unchanged, and the database dashboard is a wall of green: p99 query latency sitting at 0.6ms, zero entries in the slow query log, CPU under 20 percent.

The endpoint takes 900ms. The database says it did 340ms of work. Nobody can explain the other 560ms, and the database is adamant that it is not the problem.

The database is telling the truth. It answered 412 queries and every single one of them was fast.

The metric that lies by being accurate

This one took me a while to internalise, because every instinct says to trust the database metrics when the database metrics are healthy.

Query latency is the wrong unit. A dashboard reporting p99 query latency of 0.6ms is measuring one query at a time, and it will keep reporting 0.6ms whether a request issues one query or four hundred. The number is correct and it describes nothing you care about.

What matters is queries per request. That number is almost never on a dashboard, because it lives on the boundary between the application and the database and neither side considers it their business. The application team watches endpoint latency. The database team watches query latency. Query count per request falls in the gap.

The connection pool was the only thing complaining, and it was complaining about the wrong thing. Pool saturation looks like a capacity problem, so the reflex is to raise the pool size. That makes it worse, because the pool is not short of connections, it is short of connections that are free. Each request was holding one for most of a second while doing almost no database work.

The line of code that does not look like I/O

Here is the shape of it in JPA, and the reason it survives code review.

List<Order> orders = orderRepository.findByCustomerId(customerId);

BigDecimal total = BigDecimal.ZERO;
for (Order order : orders) {
    for (OrderItem item : order.getItems()) {   // network call, every iteration
        total = total.add(item.getLineTotal());
    }
}

Six lines. One of them is a network round trip that fires once per order, and it is spelled order.getItems().

That is the part I keep coming back to. The problem is not that engineers do not know what N+1 is. Everyone knows what N+1 is. The problem is that the ORM deliberately makes remote data access look like local field access, which is the entire value proposition of an ORM and also the reason this bug ships. You cannot see I/O in that loop because there is nothing there that looks like I/O.

Lazy loading returns a proxy. The proxy does nothing until you touch it. Touching it inside a loop is what turns a constant into a multiplier.

sequenceDiagram
    participant App as Application
    participant Pool as Connection pool
    participant DB as Database

    App->>Pool: checkout connection
    App->>DB: SELECT * FROM orders WHERE customer_id = ?
    DB-->>App: 200 rows
    loop once per order, 200 times
        App->>DB: SELECT * FROM order_items WHERE order_id = ?
        DB-->>App: 5 rows
    end
    App->>Pool: return connection
    Note over Pool,DB: Connection held ~700ms.<br/>Database busy for ~120ms of it.

The cost is the round trip, not the query

A single indexed lookup on a primary key might take the database 0.3ms of actual work. The request does not pay 0.3ms. It pays:

• the round trip on the wire, which is roughly 0.15ms to 0.5ms within an availability zone and considerably more across one
• statement parsing and plan lookup, cheap per statement and not free at four hundred of them
• driver level result set allocation and entity hydration on the JVM side
• and the serialised waiting, because each iteration of that loop blocks until the previous answer arrives

Four hundred sequential round trips at 0.5ms each is 200ms of a thread doing nothing but waiting, with a pooled connection checked out the entire time. The database was busy for a fraction of it.

The arithmetic gets worse when the application and the database sit in different availability zones, which is common enough in multi-AZ deployments that people forget it is happening. At 1.2ms per round trip, the same loop costs nearly half a second, and none of the individual queries got any slower.

There is a family resemblance here to what happens when reasoning latency ends up inside a database transaction. Different cause, same shape: a pooled connection held open across something that is not database work, and a pool that saturates while the database sits idle.

Why it never shows up before production

Four things line up to keep this invisible until it is not.

The dev database is on localhost. Loopback round trips are around 0.05ms, so four hundred of them cost 20ms and nobody notices. Move the same code to a database three network hops away and the identical loop costs 200ms or more. The code did not change, the distance did.

The dev dataset is small. A seeded account with 8 orders issues 9 queries. The multiplier is real, and 9 is not a number that makes anyone look twice. N is the variable, and in development N is always small.

Tests assert on correctness, not on query count. The loop returns the right total. It returns the right total using one query or four hundred, and no assertion in the suite can tell the difference.

Pagination masks it, until it does not. An endpoint capped at 20 items per page issues 21 queries, which is survivable. Then someone adds an export feature, or raises the page limit for an internal tool, or a customer with 800 orders signs up. The bug was always there. The cap was doing the work. This is the same class of surprise as pagination that degrades with depth, except here the page size is the fuse rather than the offset.

The obvious fix and the trap inside it

Ask anyone how to fix N+1 and they will say join. They are right, and there is a sharp edge about two steps in.

@Query("SELECT o FROM Order o JOIN FETCH o.items WHERE o.customerId = :id")
List<Order> findWithItems(@Param("id") Long id);

One query. Problem solved, for exactly one collection.

Now fetch a second collection in the same query. Two hundred orders, each with 5 items and 3 shipments, and the join produces 200 by 5 by 3 rows. Three thousand rows over the wire to represent two hundred objects. Hibernate deduplicates the entities in memory so the result looks correct, which is the worst possible outcome, because the code is now wrong in a way that returns the right answer.

Hibernate refuses this outright when both collections are List, throwing MultipleBagFetchException. Engineers hit that exception, search it, find advice to change the collections to Set, and do that. The exception goes away. The cartesian product does not. You have silenced the guardrail and kept the bug.

flowchart TB
    Q["One query, two JOIN FETCH collections"] --> ROWS["200 orders x 5 items x 3 shipments"]
    ROWS --> WIRE["3000 rows transferred"]
    WIRE --> DEDUP["Hibernate deduplicates in memory"]
    DEDUP --> RESULT["200 correct objects"]
    RESULT --> HIDDEN["Correct output, 15x the transfer"]

What actually works

Batch loading is the setting most teams should reach for first, and most have never touched it.

@OneToMany(mappedBy = "order", fetch = FetchType.LAZY)
@BatchSize(size = 50)
private List<OrderItem> items;

Hibernate now collects the pending proxies and resolves them in groups, issuing WHERE order_id IN (?, ?, ... ) instead of one query per parent. Two hundred orders becomes four queries rather than two hundred. It does not eliminate the pattern, it changes the constant by a factor of 50, and it requires no change to the calling code at all. For a codebase with N+1 scattered across dozens of endpoints, that ratio matters more than elegance.

Two queries and an in-memory join is the option people skip because it feels like doing the database’s job.

List<Order> orders = orderRepository.findByCustomerId(customerId);
List<Long> orderIds = orders.stream().map(Order::getId).toList();

Map<Long, List<OrderItem>> itemsByOrder = itemRepository.findByOrderIdIn(orderIds)
        .stream()
        .collect(Collectors.groupingBy(OrderItem::getOrderId));

Two round trips, no cartesian product, no duplicate transfer, and it composes cleanly to any number of collections. This is what GraphQL’s DataLoader does underneath, and the fact that an entire library exists to do this in the GraphQL ecosystem should tell you how default the N+1 shape is once resolvers enter the picture.

Projections are the one people forget. If the endpoint needs a total, fetching entity graphs to sum a column is expensive in a way that has nothing to do with query count. Selecting the aggregate directly skips hydration entirely.

Make the invisible thing fail a test

Every fix above is local. Someone adds a getter inside a loop next quarter and you are back where you started, because nothing in the pipeline can see the difference between one query and four hundred.

The durable answer is to assert on query count.

@Test
void orderHistoryStaysWithinQueryBudget() {
    QueryCountHolder.clear();

    orderService.getHistory(customerId);   // seeded with 200 orders

    QueryCount counted = QueryCountHolder.getGrandTotal();
    assertThat(counted.getSelect())
            .as("order history should not scale queries with order count")
            .isLessThanOrEqualTo(5);
}

Datasource proxies such as datasource-proxy or the Hibernate statistics API both expose this. The mechanism matters less than the assertion existing, because a budget of five queries turns an invisible performance regression into a red build, and a red build is a thing engineers respond to.

Seed the fixture with enough rows for the multiplier to bite. A test with 8 orders passes a query budget that a test with 200 orders would fail, which is the exact trap that let the bug through in the first place.

What I would check tomorrow

Log query counts per request in production, tagged by endpoint, and sort descending. Not query latency. Count. Most teams find at least one endpoint issuing an order of magnitude more queries than anyone believed, and it is usually not the endpoint they would have guessed.

Then look at what the pool is doing during those requests. Connection pool utilisation climbing while database CPU stays flat is close to a signature. It says connections are being held rather than used, and N+1 is the most common reason for that gap.

The thing I find genuinely annoying about this bug is that it punishes exactly the abstraction people adopted an ORM to get. Lazy loading is a good idea. Proxies are a good idea. Making remote data look local is the whole point, and it works right up until the loop that touches it is the difference between one round trip and four hundred, at which point the abstraction has quietly handed you a distributed systems problem dressed up as a for loop.