Skip to main content
the lies your orm tells you

Detecting N+1 in Production

4 min read Chapter 2 of 30

Detecting N+1 in Production

The worst N+1 queries are the ones that pass code review, pass integration tests, and perform fine against your 50-row dev database. They detonate three months later when the table has 200,000 rows and the page load time goes from 300ms to 14 seconds.

Detection must be automated. Relying on a developer to spot a hidden N+1 during code review is not a strategy.

Hibernate Statistics

The lowest-friction approach. Add one property:

spring:
  jpa:
    properties:
      hibernate:
        generate_statistics: true

Hibernate logs a summary after every session:

Session Metrics {
    12345 nanoseconds spent preparing 101 JDBC statements;
    98765432 nanoseconds spent executing 101 JDBC statements;
}

The problem: this logs to your application log. Nobody reads application logs proactively. You need to extract the statement count and feed it into a metric.

@Component
public class HibernateStatisticsExporter {

    @Autowired
    private EntityManagerFactory entityManagerFactory;

    @Scheduled(fixedRate = 60_000)
    public void exportStats() {
        var stats = entityManagerFactory.unwrap(SessionFactory.class).getStatistics();
        long queryCount = stats.getQueryExecutionCount();
        long slowestMs = stats.getQueryExecutionMaxTime();
        String slowestQuery = stats.getQueryExecutionMaxTimeQueryString();

        // Push to your metrics system
        Metrics.gauge("hibernate.query.count", queryCount);
        Metrics.gauge("hibernate.query.slowest_ms", slowestMs);

        stats.clear();
    }
}

Runtime overhead: negligible. Hibernate already tracks this data internally. Enabling statistics makes it accessible but does not add instrumentation cost.

datasource-proxy for Test-Time Detection

This is the approach that catches N+1 before deployment. datasource-proxy wraps your DataSource and counts queries per request or per test method.

<dependency>
    <groupId>net.ttddyy</groupId>
    <artifactId>datasource-proxy</artifactId>
    <version>1.10</version>
    <scope>test</scope>
</dependency>
@Configuration
@Profile("test")
public class DataSourceProxyConfig {

    @Bean
    public DataSource dataSource(DataSource originalDataSource) {
        return ProxyDataSourceBuilder.create(originalDataSource)
            .name("query-counter")
            .countQuery()
            .build();
    }
}

Now write a test that asserts on query count:

@SpringBootTest
@ActiveProfiles("test")
class OrderServiceTest {

    @Autowired
    private OrderService orderService;

    @Autowired
    private DataSource dataSource;

    @Test
    void getOrderSummaries_shouldNotTriggerNPlusOne() {
        // Setup: create 10 orders with 5 items each
        createTestOrders(10, 5);

        var queryCounter = ((ProxyDataSource) dataSource)
            .getProxyConfig()
            .getQueryCountHolder();
        queryCounter.clear();

        orderService.getOrderSummaries();

        long selectCount = queryCounter.getSelectCount();
        // N+1 would produce 11 selects. A proper fetch produces 1-2.
        assertThat(selectCount).isLessThanOrEqualTo(2);
    }
}

This test fails the moment someone introduces an N+1. It runs in your CI pipeline. It catches the problem before the code reaches any environment.

p6spy for Runtime SQL Logging

p6spy intercepts all JDBC calls and logs the actual SQL with bind parameters resolved. Useful for debugging but too noisy for permanent production use.

# spy.properties
driverlist=org.postgresql.Driver
appender=com.p6spy.engine.spy.appender.Slf4JLogger
logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat
customLogMessageFormat=%(executionTime)ms|%(sql)
// application.yml for p6spy
spring:
  datasource:
    driver-class-name: com.p6spy.engine.spy.P6SpyDriver
    url: jdbc:p6spy:postgresql://localhost:5432/mydb

Output:

3ms|select o1_0.id, o1_0.customer_name from orders o1_0
1ms|select i1_0.order_id, i1_0.id, i1_0.price from order_items i1_0 where i1_0.order_id=1
1ms|select i1_0.order_id, i1_0.id, i1_0.price from order_items i1_0 where i1_0.order_id=2
1ms|select i1_0.order_id, i1_0.id, i1_0.price from order_items i1_0 where i1_0.order_id=3

The repetitive pattern is immediately visible. But you still need a human to look at it.

The Automated Pipeline

The right approach combines these tools:

  1. Development: p6spy enabled, SQL logged to console. Developers see the queries as they code.
  2. CI/CD: datasource-proxy with query count assertions. Tests fail on N+1 regressions.
  3. Production: Hibernate statistics exported to metrics. Alert when query count per request exceeds a threshold.
// A reusable test utility for query count assertions
public final class QueryAssertions {

    public static void assertMaxQueries(
            ProxyDataSource dataSource,
            int maxSelects,
            Runnable action) {
        var holder = dataSource.getProxyConfig().getQueryCountHolder();
        holder.clear();

        action.run();

        long selects = holder.getSelectCount();
        if (selects > maxSelects) {
            throw new AssertionError(
                "Expected at most %d SELECT queries, but executed %d. Likely N+1 detected."
                    .formatted(maxSelects, selects));
        }
    }
}

// Usage in tests:
@Test
void orderSummary_queriesAreBounded() {
    createTestOrders(50, 10);
    QueryAssertions.assertMaxQueries(proxyDataSource, 3, () -> {
        orderService.getOrderSummaries();
    });
}

The overhead of datasource-proxy in tests is under 5% execution time. The overhead of catching an N+1 before production is incalculable.