SQL Logging and Statistics

See Every Statement

You cannot tune what you cannot see. In development turn on SQL logging with bound parameters and Hibernate statistics. (spring.jpa.show-sql prints to stdout without parameters; logger categories are better.)

Logging Setup

application-dev.yml

logging:
  level:
    org.hibernate.SQL: DEBUG                 # the SQL
    org.hibernate.orm.jdbc.bind: TRACE       # parameter values (Hibernate 6)
    org.hibernate.stat: DEBUG                # per-query timing
    org.hibernate.SQL_SLOW: INFO             # slow query log
spring:
  jpa:
    properties:
      hibernate:
        format_sql: true
        generate_statistics: true
        session.events.log.LOG_QUERIES_SLOWER_THAN_MS: 200

Example output

DEBUG org.hibernate.SQL : select p1_0.id,p1_0.name,p1_0.price from products p1_0 where p1_0.category_id=?
TRACE org.hibernate.orm.jdbc.bind : binding parameter (1:BIGINT) <- [2]
DEBUG org.hibernate.stat.internal.StatisticsImpl : HHH000117: HQL: select p from Product p where p.category.id = :id, time: 4ms, rows: 25
INFO  org.hibernate.SQL_SLOW : Slow query took 512 milliseconds [select ... from orders o1_0 where o1_0.created_at>?]

Session Metrics

Spotting N+1

With statistics on, Hibernate logs a summary at the end of every session. The number to watch is JDBC statements executed:

curl localhost:8080/api/orders?userId=12

Example output

INFO  o.h.e.i.StatisticalLoggingSessionEventListener : Session Metrics {
    412300 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    1893400 nanoseconds spent preparing 21 JDBC statements;
    48211700 nanoseconds spent executing 21 JDBC statements;     <- 1 + 20: an N+1!
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    ...
}

Counting Queries

Example

Why the count matters: loading 20 orders and touching a lazy collection on each one costs 21 round trips; one JOIN FETCH costs 1 (the fixes are taught in the medium level, Fetching module):

import java.util.*;

public class Main {
    static int statements = 0;
    static final double LATENCY_MS = 1.5;      // network round trip app -> DB

    static List<Integer> selectOrders() { statements++; return List.of(1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20); }
    static int selectItemsOf(int orderId) { statements++; return orderId % 3 + 1; }

    public static void main(String[] args) {
        int items = 0;
        for (int id : selectOrders()) items += selectItemsOf(id);    // lazy loading in a loop
        System.out.printf("lazy loop : %d statements, ~%.1f ms network, %d items%n", statements, statements * LATENCY_MS, items);

        statements = 0;
        statements++;                       // select o, i from orders o join fetch o.items i
        System.out.printf("join fetch: %d statement,  ~%.1f ms network, %d items%n", statements, statements * LATENCY_MS, items);
    }
}

Output

lazy loop : 21 statements, ~31.5 ms network, 41 items
join fetch: 1 statement,  ~1.5 ms network, 41 items