Performance audit медленного read-case

1. Performance audit как сценарий

Когда разработчик говорит «у нас тормозит каталог», это звучит примерно как «у меня болит… ну, где-то». Вроде правда, но лечить по такому описанию можно разве что прикладыванием подорожника к ноутбуку. Performance audit в persistence layer начинается с очень земной мысли: мы оптимизируем не абстрактную систему, а конкретный read-case, который можно повторить одинаково два раза подряд и получить сравнимый результат.

Если вы попробуете «ускорять вообще всё», вы мгновенно утонете в шумах: разные запросы, разные параметры, разные кэши, разные транзакционные границы, прогрев, фоновые задачи, миграции, автозапросы Hibernate и т.д. Поэтому наш сегодняшний стиль — почти скучный. Мы фиксируем один use case, снимаем baseline, классифицируем проблему по SQL и статистике, выбираем один рычаг изменения и готовим корректный повторный прогон. Всё. Никакой магии — только упрямство и цифры.

Чтобы эту мысль удержать, полезно запомнить простую формулу дня:

Use case → baseline → SQL-симптом → statistics-подтверждение → EXPLAIN (если нужно) → одно изменение

И вот теперь можно говорить про «схему аудита» как про настоящую процедуру, а не про вдохновение.

2. Шаг 0: фиксируем один read-case и параметры

Перед тем как смотреть на SQL, хочется сразу «что-то улучшить» — это естественно. Но если не зафиксировать сценарий, вы будете оптимизировать не систему, а собственные эмоции. В этом шаге мы делаем то, что обычно пропускают: выбираем один read-case, определяем его параметры (фильтры, сортировка, размер страницы) и решаем, где проходит его транзакционная граница. Это превращает «случайное тормозит» в повторяемый эксперимент.

В Commerce Persistence Lab удобные кандидаты на такой read-case — это, например, «страница активных товаров в админке» или «список новых заказов для обработки». Важно, что это именно чтение, без бизнес-эффектов, и оно должно запускаться одинаково: один и тот же статус, один и тот же pageSize, одна и та же сортировка.

Часто я предлагаю студентам мысленно подписать read-case как тест-кейс, даже если вы пока не пишете тест:

«CatalogPage: status=ACTIVE, sort=name, pageSize=50»

Это помогает не расплываться.

Технически нам полезно также обеспечить одинаковую среду: один и тот же профиль логов (sql-trace, stats), один и тот же набор данных (желательно не «вчера seeded, сегодня другое»), и желательно одна и та же логика транзакции. В проекте у нас open-in-view=false, поэтому read-case должен жить в сервисе/квери-сервисе (а не быть случайным обходом сущностей где-то «после транзакции»).

Небольшой пример «фиксируем вход» в коде (без философии, просто чтобы показать стиль):

import java.util.UUID;

/**
 * Параметры зафиксированного read-case: так сценарий становится повторяемым.
 * Идея: одинаковый вход → сравнимые замеры "до/после".
 */
public record CatalogPageRequest(
    UUID auditRunId, // Идентификатор прогона: удобно для корреляции логов/метрик
    int pageSize,    // Размер страницы фиксируем, чтобы не "улучшить" время случайно
    String sort      // Сортировка часто влияет на план запроса и стоимость ORDER BY
) {}

Смысл такого объекта не в том, что «нужен обязательно рекорд». Смысл в том, что у сценария появляются границы и параметры, а значит его можно запускать одинаково.

3. Шаг 1: baseline (время, Stats, SQL)

Когда базовый сценарий выбран, очень хочется сразу полезть в JOIN FETCH или индексы. Но baseline — это якорь, без которого вы потом не поймете, стало лучше или вам просто повезло с прогревом. Здесь важно признать неприятную истину: время само по себе — плохой диагноз, потому что оно не объясняет причину. Поэтому baseline мы снимаем «тройкой»: минимальная длительность, статистика и SQL-форма.

На уровне кода удобно иметь одну маленькую утилиту, которая запускает use case, снимает время и читает один и тот же набор метрик. Тогда baseline, проверка гипотезы и повторный прогон говорят на одном языке: elapsedMs, queryCount, prepareStatementCount, entityLoadCount, collectionFetchCount, flushCount.

Пример простого «снимка» (без фанатизма, 8–9 строк — чтобы было видно идею):

import org.hibernate.stat.Statistics;

/**
 * Снимок ключевых метрик, чтобы сравнивать прогоны "до/после" не на уровне ощущений.
 */
public record AuditSnapshot(
    long elapsedMs,              // Время выполнения use case (грубый, но нужный ориентир)
    long queryCount,             // Сколько query-based executions прошло через Hibernate
    long prepareStatementCount,  // Сколько JDBC PreparedStatement реально понадобилось
    long entityLoadCount,        // Сколько сущностей было загружено (может вскрывать overfetching)
    long collectionFetchCount,   // Сколько раз догружались коллекции (часто признак N+1)
    long flushCount              // Сколько flush случилось в "чтении" (подозрительно для read-case)
) {
    public static AuditSnapshot from(Statistics st, long elapsedMs) {
        // Забираем один и тот же набор счётчиков для baseline и повторного прогона.
        return new AuditSnapshot(
            elapsedMs,
            st.getQueryExecutionCount(),
            st.getPrepareStatementCount(),
            st.getEntityLoadCount(),
            st.getCollectionFetchCount(),
            st.getFlushCount()
        );
    }
}

Теперь можно сделать «один прогон» сценария. Заметьте, здесь нет попытки стать JMH: нам не нужен идеальный микробенчмарк, нам нужна воспроизводимая диагностика.

import org.hibernate.stat.Statistics;

public AuditSnapshot run(Statistics st, Runnable useCase) {
    // Важно сбросить счетчики, иначе прогоны будут "накапливаться" и врать.
    st.clear();

    long started = System.nanoTime();
    // Здесь запускается фиксированный read-case (один и тот же вход).
    useCase.run();
    long elapsedMs = (System.nanoTime() - started) / 1_000_000;

    // Снимаем snapshot сразу после выполнения, чтобы baseline и after сравнивались по тем же полям.
    return AuditSnapshot.from(st, elapsedMs);
}

Параллельно с этим вы включаете SQL trace (как мы обсуждали в лекции 1), чтобы видеть форму запросов. И вот у вас появляется baseline вида: «240 мс, 18 запросов, 120 entity loads, 30 collection fetches, flushCount=0». Это уже не «медленно», это конкретика.

4. Шаг 2: классифицируем проблему по SQL

Когда вы открываете SQL-лог, мозг разработчика часто ведет себя как кот на лазерной указке: внимание прыгает по строчкам, глаз цепляется за страшные left outer join, рука тянется менять аннотации. В этом шаге мы делаем наоборот: читаем лог структурно, чтобы определить тип проблемы. И только после этого выбираем инструмент исправления, а не наоборот.

В реальности у нас обычно встречаются четыре «характерных сюжета».

Первый сюжет — повторяющиеся SELECT одинаковой формы с разными параметрами. Это выглядит как один root query, а потом много запросов вида select ... from product_details where product_id=? или select ... from order_item where order_id=?. Часто это либо N+1, либо «ленивая догрузка по циклу», либо маленький @BatchSize мог бы помочь, либо нужен fetch-plan для конкретного use case.

Второй сюжет — один запрос, но он очень широкий: много JOIN, много колонок, много строк из-за to-many. В логах он выглядит как «вроде один запрос», но по факту вы тащите огромный result set, дублируете данные по строкам и делаете дорогое чтение для простого списка. Это типичный случай, когда надо подумать о projection/read-model, а не радоваться «о, всего один запрос».

Третий сюжет — в read-case внезапно появляются UPDATE или flush перед запросом. Это значит, что вы где-то мутировали managed-entity (возможно, даже случайно: trim(), смена поля, изменение embeddable, или setter с побочным эффектом). Такой сценарий ломает идею «чтение должно быть чтением», а заодно часто портит время и создает лишнюю нагрузку на базу.

Четвертый сюжет — запросов мало, но конкретный запрос тяжелый: фильтры и сортировки заставляют PostgreSQL делать дорогое сканирование, сортировку, join по неудачному плану. Это тот момент, когда EXPLAIN из лекции 3 становится реально полезным, и разговор об индексе перестает быть абстрактным.

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

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

5. Шаг 3: проверяем гипотезу по Statistics

SQL-лог показывает форму проблемы, но иногда мы легко сами себя обманываем. Например, кажется, что запросов «немного», а по факту их 60, просто они перемешаны. Или кажется, что N+1 исчез, но коллекции все еще догружаются. В этом шаге мы используем Statistics как «сухой отчет бухгалтера»: он не спорит, он просто фиксирует количество событий.

Идея проста: после того как вы глазами классифицировали проблему, вы смотрите на соответствующие счетчики. Если вы подозревали повторяющиеся secondary selects, то prepareStatementCount обычно быстро ползёт вверх, а collectionFetchCount и/или entityLoadCount часто взлетают вместе с ним. queryExecutionCount здесь тоже полезен как быстрый сигнал, но не заменяет эти счётчики и сам SQL-трейс. Если вы подозревали wide SELECT, то запросов может быть мало, но entityLoadCount будет неожиданно большим (вы загрузили кучу сущностей, которые вам вообще не нужны), а иногда вы увидите, что под капотом материализовались коллекции.

Если вы подозревали «почему-то был flush», то flushCount внезапно станет больше нуля, хотя вы «просто читали». Это очень полезный счетчик именно для read-case, потому что он быстро вытаскивает наружу «грязное чтение с побочными эффектами».

Мини-пример «читаем счетчики как диагноз», без длинного кода:

import org.hibernate.stat.Statistics;

public String quickDiagnosis(Statistics st) {
    // Короткая строка для лога/консоли: дисциплинирует, потому что это "цифры", а не ощущения.
    return "queryCount=" + st.getQueryExecutionCount()
        + ", prepareStatementCount=" + st.getPrepareStatementCount()
        + ", entityLoadCount=" + st.getEntityLoadCount()
        + ", collectionFetchCount=" + st.getCollectionFetchCount()
        + ", flushCount=" + st.getFlushCount();
}

В реальном audit-цикле вы не ограничиваетесь одной строкой, но даже такой «свернутый отчет» уже дисциплинирует: вместо «кажется стало лучше» появляется «queries упали с 18 до 2, collections с 30 до 0».

6. Шаг 4: находим доминирующий запрос

Очень распространенная ошибка в оптимизации — чинить первое, что попалось на глаза. Это как лечить простуду измерением температуры в локте: цифры есть, пользы мало. В performance audit нам нужен доминирующий источник стоимости: запрос или шаблон запросов, который действительно определяет нагрузку и время сценария. Этот шаг часто экономит больше всего времени — потому что вы перестаете оптимизировать «всё по чуть-чуть» и начинаете оптимизировать «самое дорогое».

Для поиска доминирующего SQL обычно хватает двух приемов. Первый — комментарий к запросу (если вы используете Hibernate API через Session), чтобы легко найти SQL-блок в логе. Второй — просто дисциплина: вы берете root query вашего use case и смотрите, что идет после него.

Пример с комментарием (сейчас это именно диагностика, не архитектура):

import org.hibernate.Session;

// Достаем Hibernate Session, чтобы добавить SQL-комментарий и легче находить запрос в trace.
Session session = entityManager.unwrap(Session.class);

return session.createQuery("from Product p where p.status = :s", Product.class)
    .setComment("audit: catalog-page") // Этот комментарий появится в SQL как /* ... */.
    .setParameter("s", ProductStatus.ACTIVE) // Фиксируем параметр: статус — часть сценария.
    .setMaxResults(50) // Фиксируем размер страницы: иначе сравнение "до/после" невалидно.
    .getResultList();

Дальше вы в SQL trace находите блок с /* audit: catalog-page */ и анализируете его целиком: root query, secondary selects, догрузки коллекций, неожиданные записи. На этом шаге важно не распыляться: если у вас в сценарии 18 запросов, часто 15 из них будут «одного семейства», и вот это семейство и есть главная цель.

Если же запрос один, но тяжелый, то «доминирующий запрос» очевиден — это он. Тогда вы переходите к EXPLAIN (как обсуждали в прошлой лекции) уже для конкретного SQL, а не «для идеи запроса».

7. Шаг 5: выбираем один рычаг

На этом этапе у новичка обычно возникает желание сделать сразу всё: и JOIN FETCH, и projection, и индекс, и @BatchSize, и «давайте еще caching включим». Это нормально, потому что мозг любит ощущение деятельности. Но инженерный audit устроен иначе: в одном цикле мы меняем один фактор, иначе вы не поймете, что именно сработало (и сработало ли вообще).

Чтобы выбрать рычаг, достаточно задать себе очень практический вопрос: «Где именно рождается стоимость?» Если стоимость рождается от количества запросов, первым рычагом обычно будет fetch-plan или сужение read-model. Если стоимость рождается от ширины данных (overfetching), первым рычагом часто будет projection. Если стоимость рождается от плана БД (сканирование, сортировка), тогда уже имеет смысл говорить про индекс или переписывание фильтра/сортировки.

Покажу несколько мини-примеров «один рычаг — один шаг», без углубления в тему fetching (она уже была раньше), но чтобы было видно, как это выглядит в коде.

Если проблема выглядит как N+1 на to-one/to-many, то первым рычагом может быть отдельный read-method с EntityGraph:

import org.springframework.data.jpa.repository.EntityGraph;
import org.springframework.data.jpa.repository.JpaRepository;

public interface PurchaseOrderRepository extends JpaRepository<PurchaseOrder, Long> {

    // EntityGraph задает fetch-plan под конкретный read-case:
    //     подтянем customer и items одним способом, чтобы не ловить N+1 на ленивых связях.
    @EntityGraph(attributePaths = {"customer", "items"})
    java.util.List<PurchaseOrder> findTop20ByStatusOrderByCreatedAtDesc(OrderStatus status);
}

Если проблема в том, что вы тащите entity-граф ради списка, то первым рычагом часто становится projection (сужаем read-model):

import java.util.List;

// Projection вместо сущностей: берем только то, что нужно списку (id/sku/name).
//     Это снижает overfetching и часто уменьшает стоимость materialization.
List<ProductRow> rows = entityManager.createQuery("""
    select new com.example.commerce.catalog.dto.ProductRow(p.id, p.sku, p.name)
    from Product p
    where p.status = :status
    order by p.name
    """, ProductRow.class)
    .setParameter("status", ProductStatus.ACTIVE) // Параметр фиксирует сценарий (baseline сравним).
    .getResultList();

Если проблема в том, что read-case внезапно «пишет», рычагом будет не fetch и не индекс, а устранение мутации или перевод чтения в read-only режим (для чистоты эксперимента):

import java.util.List;

// Read-only hint помогает не тратить время на dirty checking и уменьшает риск flush "в чтении".
List<Product> products = entityManager.createQuery("""
    select p from Product p where p.status = :status
    """, Product.class)
    .setParameter("status", ProductStatus.ACTIVE) // Те же параметры — та же точка сравнения.
    .setHint("org.hibernate.readOnly", true) // Подчеркиваем, что этот use case должен быть чистым read.
    .getResultList();

А если вы видите, что запрос сам по себе тяжелый (мало запросов, но долго), то рычагом становится EXPLAIN (и уже потом — индексы). Здесь важно: мы не «оптимизируем индексами в вакууме», мы связываем индекс с конкретным SQL:

explain
select p.id, p.sku, p.name
from product p
where p.status = 'ACTIVE'
order by p.name

Эти примеры специально короткие, потому что ключевая мысль не в синтаксисе. Ключевая мысль: сначала вы диагностировали тип проблемы, потом выбрали один рычаг, и только потом сделали одно изменение.

8. Шаг 6: повторный прогон

После одного изменения очень хочется победно написать в чат команды: «Я ускорил каталог на 73%». Удержитесь. На этом шаге наша задача — подготовить корректный повторный прогон: тот же вход, тот же набор данных, тот же порядок действий, те же включенные профили логов. Сейчас важно не красиво объявить победу, а обеспечить, чтобы сравнение вообще имело смысл.

Технически это означает несколько скучных, но обязательных вещей: снова statistics.clear(), тот же pageSize, та же сортировка, тот же статус. Если вы измеряли «список NEW заказов», то вы снова измеряете NEW, а не внезапно PAID. Если вы снимали SQL trace на одном сценарии, вы снова находите в логе именно этот сценарий (и очень полезно, если у него есть комментарий). Если вы делали EXPLAIN, вы делаете его для того же SQL-шаблона, а не «примерно похожего».

И еще один важный момент для психики разработчика: если после изменения метрики не улучшились, это не провал. Это просто значит, что гипотеза была слабой или вы лечили не доминирующий источник стоимости. В performance audit это нормальная часть процесса: «проверили → не сработало → вернулись на шаг 4».

9. Типичные ошибки в audit read-case

В конце хочется собрать самые частые «грабли» именно вокруг процедуры аудита, а не вокруг конкретных инструментов. Эти ошибки неприятны тем, что вы можете сделать правильный EntityGraph или правильную projection — и все равно не понять, помогло ли это, потому что сам эксперимент был поставлен плохо. Поэтому этот блок — про дисциплину и воспроизводимость, а не про аннотации.

Ошибка №1: аудит без baseline.
Если вы не зафиксировали «до», то «после» превращается в литературное произведение. Кажется быстрее, кажется медленнее, «у меня на машине так было». Hibernate Statistics и минимальный замер времени нужны не для красоты, а чтобы любое изменение можно было сравнить с исходным состоянием в одинаковых условиях.

Ошибка №2: менять сразу три вещи и радоваться одной.
Очень соблазнительно одновременно переписать запрос, добавить JOIN FETCH и накатить индекс. А потом вы не знаете, что именно дало эффект, и что из этого можно безопасно оставить. В учебном audit-цикле мы принципиально меняем один фактор, чтобы связь «изменение → эффект» была доказуемой, а не интуитивной.

Ошибка №3: оптимизировать «самый красивый запрос», а не самый дорогой.
Иногда разработчик чинит root query, потому что он большой и страшный, а реальная стоимость сидит в 50 повторяющихся secondary selects. Или наоборот: он героически борется с N+1, а на деле один монстр-запрос с wide SELECT и сортировкой по неиндексированному полю съедает 95% времени. Доминирующий источник стоимости важнее эстетики.

Ошибка №4: игнорировать flushCount в read-case.
Read-case, который внезапно делает flush, часто означает, что вы мутируете managed-entity внутри чтения. Это может быть почти незаметно в коде, но очень заметно в SQL. Если вы не смотрите на flushCount, вы можете искать «плохие индексы» там, где проблема — в accidental update.

Ошибка №5: спорить с базой данных без EXPLAIN.
Бывает и наоборот: вы уверены, что запрос «должен летать», потому что «он же простой», но PostgreSQL выбирает план, где делает seq scan и сортировку в память/на диск. В этот момент любые разговоры «давайте добавим аннотацию» заканчиваются. Нужен план выполнения, потому что он объясняет цену конкретного SQL в конкретной БД.