Seeing the SQL Hibernate actually runs

Hibernate · lesson 28 of 32 · 5 min read

show-sql is not enough - bind parameters, statement counts and the N+1 you cannot see.

Open this lesson in the learning hub

Key points

  • show-sql prints statements without bind parameters, so you see the shape but not the values - which is exactly what you need when diagnosing a wrong result.
  • Turning on the binder logger fills that in, but the real problem is counting: a page that issues 300 queries prints 300 lines and looks like normal activity.
  • A statement counter is what turns that into a signal. Asserting a query count in a test catches an N+1 the moment it is introduced, rather than in production.
  • Datasource proxies such as datasource-proxy or p6spy log the real statement with parameters inline, and can log slow queries only - far more usable than raw Hibernate logging.
  • The persistence context hides work too. A getReference that is never touched issues nothing; the same code touching one field issues a select. Reading the log without knowing that is confusing.
  • In production, log a summary rather than statements: query count and total time per request, tagged with the endpoint. That surfaces regressions without the cost of logging every statement.

Example

# Development only - the second line is what adds bind parameters.
logging:
  level:
    org.hibernate.SQL: DEBUG
    org.hibernate.orm.jdbc.bind: TRACE      # Hibernate 6
    # org.hibernate.type.descriptor.sql: TRACE   # Hibernate 5

# Statistics - the numbers, rather than a wall of statements.
spring:
  jpa:
    properties:
      hibernate:
        generate_statistics: true
        session:
          events:
            log:
              LOG_QUERIES_SLOWER_THAN_MS: 50

---

// The test that stops N+1 ever reaching production.
@Test
void loadingOrdersDoesNotNPlusOne() {
    Statistics stats = entityManagerFactory
            .unwrap(SessionFactory.class).getStatistics();
    stats.clear();

    List<Order> orders = orderRepository.findAllWithLines();
    orders.forEach(o -> o.getLines().size());   // touch the association

    // One query, not 1 + N. This assertion is the whole point:
    // it fails the build the day someone removes the JOIN FETCH.
    assertThat(stats.getPrepareStatementCount()).isEqualTo(1);
}

/*
 * What generate_statistics prints per session:
 *
 *   Session Metrics {
 *       1234567 nanoseconds spent acquiring 1 JDBC connection;
 *       89012345 nanoseconds spent preparing 247 JDBC statements;   <- 247
 *       12345678 nanoseconds spent executing 247 JDBC statements;
 *       0 nanoseconds spent performing 0 L2C puts;
 *   }
 *
 * 247 statements for one request is an N+1, whatever the page looks like.
 */

Count statements rather than reading them - an asserted query count in a test is what stops N+1 from ever shipping.

This is a reading copy. The full lesson — with the visual explainer, the interactive lab and a Run button for the code — lives in the Hibernate course, and every lesson in it is listed on the Hibernate contents page.