Как доказывать N + 1: trace и statistics

1. «Кажется, тормозит»

У начинающего разработчика есть естественная привычка: если что-то медленно, значит «надо оптимизировать». Проблема в том, что без измерения вы не знаете, что именно оптимизировать. Это как лечить температуру, не измерив её: можно, конечно, «на всякий случай» выпить всё из аптечки, но это не медицина — это квест «угадай таблетку». Hibernate в этом смысле особенно коварен, потому что он умеет делать SQL не только там, где вы ожидаете, но и «по дороге»: при обходе коллекции, при логировании, при вызове toString(), при size() коллекции и так далее.

Поэтому нам нужен baseline — отправная точка, с которой сравнивают изменения. Baseline отвечает на вопрос: «Сколько SQL реально ушло в базу, когда я сделал вот этот сценарий чтения, на вот этих данных, внутри вот такой транзакции». И здесь важно слово «тот же самый». Если вы один раз запускали на 5 заказах, а второй раз на 50, вы уже не сравниваете: вы просто смотрите два разных фильма и пытаетесь понять, почему у них разные концовки.

Поэтому действуем как в лаборатории: сначала фиксируем сценарий чтения как метод, который можно вызвать повторяемо; затем фиксируем «инструменты наблюдения» (SQL trace и statistics); затем делаем замер; и только потом обсуждаем, что менять. Мы пока не лечим N+1 — мы учимся его доказывать.

Чтобы дальше не расползтись по разным демо, зафиксируем один и тот же сценарий: список заказов плюс доступ к customer.email. Он станет baseline на несколько лекций подряд, и дальше мы будем менять не предмет измерения, а только то, как сам сценарий читает данные.

2. Два микроскопа: SQL trace и Statistics

Когда говорят «посмотри SQL», обычно имеют в виду логи org.hibernate.SQL. Это уже очень полезно: вы видите, какие SELECT реально ушли в PostgreSQL. Но проблема логов в том, что они похожи на «видеозапись с места преступления»: всё видно, но если вы не умеете быстро считать и сравнивать, можно утонуть в деталях. Именно поэтому нам нужен второй микроскоп — Hibernate Statistics. Он не показывает текст запросов, зато показывает цифры: сколько statement’ов подготовлено, сколько entity загружено, сколько коллекций инициализировано. Это похоже на приборную панель автомобиля: она не расскажет, как устроен двигатель, но по стрелкам вы понимаете, что машина реально делает.

Чтобы не путаться, зафиксируем сравнение в таблице — это тот редкий случай, когда таблица лучше любого художественного абзаца:

И важная оговорка: query count можно получить разными способами, но в рамках курса самый прямой и честный путь — брать его из Hibernate Statistics, потому что это встроенный инструмент. Позже можно обсуждать DataSource-proxy и прочие штуки, но мы сейчас не на выставке «какой инструмент моднее». Мы находимся в лаборатории: чем проще и воспроизводимее — тем лучше.

4. Включаем SQL trace и statistics

SQL trace и statistics не обязаны быть включены всегда. Более того, если включить всё и везде, логи станут такими шумными, что вы начнёте мечтать о жизни лесника без интернета (там тоже есть N+1, но это комары). В нашем курсе для этого и придуманы профили: sql-trace включает подробный SQL, а stats включает статистику.

Ниже — минимальные фрагменты конфигурации, которые дают нам «видимость» без превращения приложения в логогенератор. Обратите внимание: мы не используем hibernate.show_sql как “println для SQL”, а используем нормальный logging — так проще контролировать уровень и формат.

# application-sql-trace.yml
logging:
  level:
    org.hibernate.SQL: DEBUG         # Печатаем сам SQL
    org.hibernate.orm.jdbc.bind: TRACE # Печатаем bind-параметры (значения ?)

spring:
  jpa:
    properties:
      hibernate:
        format_sql: true             # Делаем SQL в логах читабельнее

Если вы включите такой профиль, вы увидите сам SQL (org.hibernate.SQL) и bind-параметры (org.hibernate.orm.jdbc.bind). Иногда параметров слишком много — но для диагностики N+1 это очень полезно, потому что вы увидите, что повторяется один и тот же запрос, только id каждый раз другой.

А статистика включается ещё проще:

# application-stats.yml
spring:
  jpa:
    properties:
      hibernate:
        generate_statistics: true # Включаем Hibernate Statistics (по умолчанию выключено)

Запускаем приложение с профилями (примерно так, способ зависит от вашего запуска):

./gradlew bootRun --args='--spring.profiles.active=local,sql-trace,stats' # Важно: профили должны совпадать при сравнении

Если вы не любите команды, можно включать профили в IDE. Главное — чтобы условия эксперимента были одинаковы для сравнения.

5. query count: счёт запросов vs время

Самая простая, но очень мощная метрика — это количество SQL-операций за один сценарий чтения. Для N+1 она особенно показательна, потому что N+1 почти всегда проявляется как линейный рост: было 20 заказов — стало 21 запрос; стало 200 заказов — стало 201 запрос. Иногда даже хуже: если в цикле вы трогаете две lazy-связи, то получите примерно 1 + N + N, то есть 1 + 2N. И вот это «2N» — уже как раз тот момент, когда база начинает нервно кашлять.

Почему не надо начинать с измерения времени? Потому что время очень шумное. Сегодня ваш ноутбук решил обновить IDE, завтра у PostgreSQL кэш прогрелся, послезавтра вы запускали это после миграций, и всё было хуже. А query count — это почти всегда чёткая структурная метрика: либо запрос ушёл, либо нет. Она не объясняет всё (один тяжёлый запрос может быть хуже десяти лёгких), но она отлично ловит N+1, потому что N+1 — именно структурная проблема.

В нашем курсе мы будем брать query count через Hibernate Statistics, используя getPrepareStatementCount(). Это не абсолютный универсальный счётчик всего, что могло произойти вокруг базы, а практический proxy для query count в одном лабораторном сценарии. Для ловли N+1 этого более чем достаточно: паттерн линейного роста он показывает очень надёжно.

6. Hibernate Statistics: замер query count

Когда вы впервые видите Statistics API, есть соблазн либо «не трогать, потому что страшно», либо наоборот «считать всё подряд и утонуть». Мы сделаем аккуратно: нам нужно всего три операции. Первая — получить объект Statistics. Вторая — clear() перед запуском сценария, чтобы замер не был накопительным. Третья — взять getPrepareStatementCount() после сценария и распечатать.

И держим один baseline без прыжков: список заказов и доступ к customer.email. На нём легко сначала увидеть N+1, а потом проверить, что меняется, когда список перестаёт случайно превращаться в карточку.

Сделаем небольшой helper в пакете labsupport. Он будет жить ровно там, где ему и место — в учебной инфраструктуре, а не в домене заказов (потому что заказы не должны знать, сколько SQL они породили… иначе они начнут этим гордиться).

package com.example.commerce.labsupport;

import jakarta.persistence.EntityManagerFactory;
import org.hibernate.SessionFactory;
import org.hibernate.stat.Statistics;
import org.springframework.stereotype.Component;

@Component
public class HibernateStats {
    private final Statistics stats;

    public HibernateStats(EntityManagerFactory emf) {
        // Достаём Hibernate-специфичный SessionFactory из JPA-фабрики
        this.stats = emf.unwrap(SessionFactory.class).getStatistics();
    }

    public Statistics stats() {
        // Возвращаем Statistics, чтобы в runner'е можно было clear() и читать счётчики
        return stats;
    }
}

Обратите внимание на важную деталь: мы «разматываем» EntityManagerFactory до SessionFactory через unwrap(). Это нормальный, официальный путь, когда вы хотите получить доступ к Hibernate-специфичному API в рамках Hibernate-курса. Мы не делаем это «в бизнесе» на каждую задачу, но в лаборатории — абсолютно уместно.

Теперь нам нужен воспроизводимый read-сценарий. Пусть он будет таким же, как в плане дня: читаем список заказов и печатаем orderNumber + customer.email. Именно этот getCustomer().getEmail() и будет потенциальным триггером N+1 (в зависимости от fetch-настроек и текущего контекста).

package com.example.commerce.orders.query;

import com.example.commerce.orders.entity.PurchaseOrder;
import jakarta.persistence.EntityManager;
import org.springframework.stereotype.Service;
import org.springframework.transaction.annotation.Transactional;

@Service
public class OrderReadService {
    private final EntityManager em;

    public OrderReadService(EntityManager em) {
        this.em = em;
    }

    @Transactional(readOnly = true)
    public void printOrdersWithCustomerEmail() {
        // Важно: один фиксированный запрос на root-entity (то самое "1" в N+1)
        var orders = em.createQuery("select o from PurchaseOrder o", PurchaseOrder.class)
                .getResultList();

        for (var o : orders) {
            // Доступ к o.getCustomer() потенциально может триггерить lazy-загрузку (то самое "N")
            System.out.println(o.getOrderNumber() + " " + o.getCustomer().getEmail());
        }
    }
}

Да, метод выглядит «игрушечным». Это нормально. Лабораторный метод должен быть простым, иначе вы не поймёте, что именно вызвало SQL. В реальном проекте вместо println() будет сбор DTO, но с точки зрения ORM-поведения разницы почти нет: доступ к полю — это доступ к полю.

Важно: это и есть baseline-сценарий. Дальше мы не будем изобретать новый read-метод ради нового эксперимента, а начнём разбирать именно его.

И теперь — сам замер. Нам нужен маленький runner, который выполнит сценарий и распечатает query proxy. Чтобы не тащить сюда тестовые аннотации (про тесты у нас будет отдельный модуль), сделаем CommandLineRunner под профиль, например lab.

package com.example.commerce.labsupport;

import com.example.commerce.orders.query.OrderReadService;
import org.springframework.boot.CommandLineRunner;
import org.springframework.context.annotation.Profile;
import org.springframework.stereotype.Component;

@Profile("lab")
@Component
public class NPlusOneLabRunner implements CommandLineRunner {
    private final OrderReadService service;
    private final HibernateStats hStats;

    public NPlusOneLabRunner(OrderReadService service, HibernateStats hStats) {
        this.service = service;
        this.hStats = hStats;
    }

    @Override
    public void run(String... args) {
        // 1) Очищаем счётчики, чтобы замер был "за один запуск"
        hStats.stats().clear();

        // 2) Запускаем воспроизводимый read-сценарий
        service.printOrdersWithCustomerEmail();

        // 3) Печатаем количество prepared statements как практический proxy для query count
        System.out.println("query proxy = " + hStats.stats().getPrepareStatementCount()); // query proxy = 21
    }
}

Ровно три важные строки: clear(), вызов сценария, печать счётчика. Всё. Если вы видите, что query proxy подозрительно растёт вместе с количеством заказов — у вас есть первый железобетонный сигнал.

Теперь у нас есть честный замер. Следующий инженерный вопрос — уже не «какую аннотацию дёрнуть», а какие данные этот сценарий вообще обязан читать, а какие мы тащим по привычке.

7. SQL trace: как по логу увидеть повторяющийся паттерн N+1

Цифры важны, но цифры без содержания — это как чек из магазина без списка товаров: понятно, что дорого, но непонятно, кто виноват. SQL trace как раз отвечает на вопрос «какие именно запросы повторяются». Для N+1 мы ищем очень характерную картину: один запрос на список root-entity и затем пачку одинаковых SELECT по связанным данным с разными параметрами.

Допустим, наш сценарий читает заказы, а затем трогает order.getCustomer().getEmail(). Часто лог выглядит примерно так (пример упрощён, чтобы вы не утонули в алиасах и лишних колонках):

-- 1) root query
select o.id, o.order_number, o.status, o.customer_id
from purchase_order o;

-- 2) repeated query (N times)
select c.id, c.email, c.first_name, c.last_name
from customer c
where c.id = ?;

Если у вас 20 заказов, вы увидите один root query и примерно 20 одинаковых запросов к customer (а bind-параметры будут разными). Вот это и есть повторяющийся SQL-паттерн. Сама форма запроса не обязана совпадать буква в букву, но структура будет узнаваемой: where c.id = ? повторяется много раз.

А если вы трогаете коллекцию order.getItems().size(), то повторяющийся паттерн будет другим, но идея та же:

-- 1) root query
select o.id, o.order_number
from purchase_order o;

-- 2) repeated query (N times)
select oi.order_id, oi.id, oi.product_id, oi.quantity
from order_item oi
where oi.order_id = ?;

И здесь есть тонкий момент, который часто удивляет новичков: даже size() может инициализировать коллекцию (зависит от реализации и условий), и вы внезапно платите отдельным SELECT на каждый заказ. Поэтому мы и говорили в прошлой лекции: N+1 приносит не только «явный обход items», но и «невинный доступ».

Чтобы упростить себе жизнь при чтении SQL trace, полезно придерживаться очень простого алгоритма мышления. Сначала вы ищете, какой запрос был «первым» (root list). Затем вы смотрите вниз: есть ли серия запросов с одинаковой формой. И если есть — вы проверяете, действительно ли их количество примерно равно количеству элементов в root list. Это и будет ваш N в N+1.

8. Диагностический workflow: воспроизвести → измерить → сравнить

Пока мы рассматривали инструменты по отдельности, всё выглядит довольно просто. На практике люди ломают диагностику не сложностью Hibernate, а собственной «неаккуратностью эксперимента». Поэтому важно иметь короткий, повторяемый workflow. Он выглядит почти как школьная лабораторная работа (и это хорошо, потому что школьные лабораторные — один из немногих видов искусства, где люди реально что-то измеряют).

Вот схема процесса, которую полезно держать в голове:

flowchart TD
    A[Выбираем один read-сценарий] --> B[Фиксируем одинаковые условия запуска]
    B --> C[Включаем sql-trace и stats]
    C --> D[Очищаем statistics]
    D --> E[Запускаем сценарий]
    E --> F[Смотрим query count]
    E --> G[Читаем SQL trace и ищем повторяющийся шаблон]
    F --> H[Фиксируем baseline]
    G --> H[Фиксируем baseline]

Обратите внимание: в этой лекции мы сознательно останавливаемся на этапе baseline. Если вы попытаетесь «чинить» до того, как зафиксировали baseline, вы окажетесь в типичной ловушке: «мне кажется, стало лучше» — и никто (включая вас самого через неделю) не сможет это доказать.

И ещё одно правило: сценарий должен выполняться внутри стабильной transaction boundary. В нашем примере это гарантирует @Transactional(readOnly = true) на методе printOrdersWithCustomerEmail(). Это не только про LazyInitializationException. Это ещё и про то, что вы хотите измерять поведение в нормальных условиях unit of work, а не в полуразорванном контексте.

9. Типичные ошибки при диагностике N+1

Ошибка №1: сравнивать разные сценарии и называть это “до/после”.
Очень распространённая ловушка: вы сначала измерили метод, который печатает только orderNumber, а потом измерили метод, который печатает orderNumber + customer.email + items.size(), и сделали вывод, что «стало хуже». Это не “хуже”, это просто другой сценарий с другими требованиями. Для честного сравнения меняйте один фактор за раз: либо код, либо данные, либо набор доступов к связям, но не всё одновременно.

Ошибка №2: забыть очистить статистику и получить накопительные цифры.
Hibernate Statistics по умолчанию копит значения, и если вы не сделаете clear(), то ваш “SQL count” будет суммой за несколько запусков. Это приводит к самому обидному виду ошибок: когда вы уверены, что нашли N+1, а на самом деле просто два раза запустили сценарий и сложили результаты. Дисциплина здесь проще, чем кажется: clear() всегда идёт непосредственно перед измеряемым вызовом.

Ошибка №3: пытаться доказать N+1 только временем выполнения.
Время — шумная метрика: прогрев кэшей, параллельные процессы, случайные фоновые задачи и даже то, что вы открыли 40 вкладок в браузере, могут менять результат. N+1 — структурная проблема, её надо ловить структурными сигналами: количеством запросов и повторяемыми шаблонами в SQL. Время можно смотреть потом, но начинать лучше с “сколько запросов и какие”.

Ошибка №4: запускать замер на слишком маленьком датасете и делать далеко идущие выводы.
N+1 на 2–3 строках может выглядеть «нормально»: ну да, 1 + 3 запроса — не конец света. Но именно поэтому N+1 так часто живёт в проде: на маленьких данных он не пугает. Для диагностики выбирайте сценарии, где список хотя бы десятки элементов. В лабораторном проекте это обычно решается seed-данными: если у вас есть 30–50 заказов — вы уже увидите характер проблемы.

Ошибка №5: смешивать запись и чтение в одном измеряемом сценарии.
Если внутри метода вы случайно делаете изменения (пусть даже “чуть-чуть”), Hibernate может сделать flush, появятся UPDATE, дополнительные SELECT и вы перестанете понимать, что именно вы измеряете. Для диагностики N+1 выделяйте чистый read-path и делайте метод @Transactional(readOnly = true). Это не магия оптимизации — это способ не испортить эксперимент.