Пятница, вечер. Сижу дома, ноут закрыт, телефон рядом, звонок - Grafana OnCall, P1
Открываю: 30% 5xx на критичной ручке загрузки SKU. Иду в логи и через минуту понимаю, что проблема не там. Какой-то соседний сервис посыпался и потащил за собой загрузку. Какой именно - пока неясно
Через несколько минут я понимаю, что лёг наш сервис заказов. Через десять - что лёг по OutOfMemoryError. Через сорок - что виноват комментарий, который висел в коде пол года:
// todo: тут N+1 на invoice — надо переделать через entity graph
return orders.stream()
.map(mapper::toDto)
.toList();Я открывал этот файл раз пятьдесят. Видел этот todo каждый раз. Тикета на него не завёл ни я, ни кто-либо в команде. В пятницу вечером он сработал.
Ниже - короткая история о том, как deprecated endpoint, известный N+1 и фронтовый чекбокс «Выбрать все» сложились в одну хорошую причину больше не оставлять // todo без тикета
Декорации
Spring Boot, Hibernate, PostgreSQL. Три реплики в k8s за балансировщиком, heap по 700 MB. Сервис обслуживает кабинет продавцов - заказы, статусы, накладные
Главный фигурант - ручка GET /orders. Помечена @Deprecated ещё пол года назад. Возвращает все заказы продавца без пагинации. Под ней SQL с JOIN’ами по нескольким связанным таблицам, и тот самый // todo в маппере
Рядом давно живёт новая пагинированная ручка. Фронт частично мигрировал, но на странице «Все заказы» осталась старая. Почему - расскажу ниже, и это самая интересная часть истории
Что произошло за две минуты
20:07 UTC. Алерт на соседнем сервисе - 30% 5xx на ручке загрузки SKU. В его логах Read timed out на запросах в наш сервис заказов
В наших подах java.lang.OutOfMemoryError: Java heap space. Три пода легли с интервалом в секунды, k8s SIGKILL’нул и поднял заново. Через две минуты всё работает. Через тридцать минут алерт авто-резолвится
Восстановилось само. Но «само починилось» - самая опасная фраза в постмортеме, потому что значит «починится и в следующий раз, и в следующий, пока не починится навсегда».
Чтение heap dump
Дамп на 721 MB, Eclipse MAT, два главных suspect’а. И оба из одного и того же HTTP-треда обработки GET /orders. Но в разных фазах
Фаза 1: парсинг ResultSet. 145 MB. Главный класс org.postgresql.core.Tuple, 49 051 штука. То есть до того, как Hibernate собрал хоть один entity, в памяти лежало 49 тысяч сырых JDBC-строк. Это не баг Hibernate это банальный JOIN, который умножает строки.
Фаза 2: маппинг в DTO. 155 MB. Главный класс SellerOrder (наша JPA-сущность), 23 730 штук. Hibernate дедуплицировал 49k JDBC-строк до 24k уникальных entity (нормальное поведение session cache). А дальше маппер тронул lazy-поле invoice.acceptedDate у каждого и Hibernate сходил в БД 24 тысячи раз. Тот самый // todo.
Один HTTP-запрос ≈ 300 MB heap. Два таких параллельно от одного клиента — и всё.
Балансировщик равномерно раскидал запросы по подам. Поэтому легли все три одновременно.
Важная деталь про композицию
Каждый из двух багов по отдельности прод бы не уронил.
N+1 на lazy invoice без раздутого ResultSet’а - 24k SELECT’ов и ~155 MB. Медленно, но не смертельно
SELECT без LIMIT’а, но без N+1 — 145 MB на ResultSet, мапнули, отпустили. Медленно, но не смертельно
Они срабатывают вместе, потому что N+1 удерживает entities в session до конца маппинга, а ResultSet ещё не успел освободиться к моменту его начала. Память не переиспользуется - она копится
Главный takeaway: // todo это не одиночная мина, это компонент сборки. Сам по себе он долго может лежать тихо и ждать, пока рядом не появится второй компонент.
Почему дожило до прода
Тут самое неловкое.
Deprecated endpoint не убрали, потому что на фронте на странице списка заказов есть чекбокс «Выбрать все». Он выделяет все заказы продавца для массовых операций (печать накладных, и тд)
Если перевести фронт на пагинированную ручку, «Выбрать все» начнёт выделять только текущую страницу. С точки зрения продавца это поломка: он жмёт «Выбрать все», подтверждает, и узнаёт, что половина заказов осталась неподтверждённой
Чтобы перевести фронт чисто, нужно либо переделать UX (отдельная операция «выделить вообще все»), либо завести бэкендовую массовую операцию (POST /orders/bulk-action), либо тянуть все ID отдельной лёгкой ручкой и работать по ним пагинацией
Любой из вариантов это продуктовая работа, а не техдолг. Поэтому она не делалась силами бэкенда. И поэтому @Deprecated стоял, а endpoint жил
Это не оправдание. Это объяснение. Разница в том, что объяснение позволяет принять решение: либо запускаем продуктовый трек на UX-миграцию, либо признаём, что endpoint остаётся, и тогда обязаны выставить ему лимиты и метрики
Не было ни того, ни другого.
Что бы я сделал по-другому
Не «починить N+1 пол года назад». Это слишком просто и неправда - мы видели todo сотни раз и осознанно не приоритизировали. Значит, дело не в дисциплине, а в недостающем сигнале
Метрики использования на каждый deprecated endpoint. @Deprecated без счётчика обращений это надпись на двери, в которую всё ещё ходят люди. Простой счётчик в Prometheus с разбивкой по клиенту показал бы, что 80% трафика идёт от 3–4 крупных продавцов с десятками тысяч заказов. И «когда-нибудь уберём» сразу превращается в «вот эти три клиента сломаются, давайте поговорим»
Hard limit на SQL-уровне. LIMIT 5-10к и явная ошибка, если строк больше. Пять минут работы, и OOM превратился бы в 500-ку с понятным сообщением
Тикет на каждый // todo. Todo без тикета это известная команде проблема, невидимая планированию. Команда знает, что плохо. Менеджмент видит зелёный спринт. Когда срабатывает все удивлены, но удивлены по-разному
Эпилог
// todo мы убрали. Endpoint всё ещё @Deprecated, но теперь у него есть жёсткий лимит и счётчик обращений. Продуктовый трек на UX-миграцию запланирован
Heap dump лежит у меня локально на случай, если кто-то захочет посмотреть, как выглядит ResultSet на 49 000 строк в Eclipse MAT. Зрелище, на самом деле, поучительное: видишь не код, а его физическое воплощение в памяти. И понимаешь простую вещь - байты не врут. В отличие от наших оценок «ну там не должно быть много»