150 запросов на один flush, и 4343 зелёных теста. Как я делал детектор N+1 и как он сам меня обманывал

Один open-source тайм-трекер на Symfony имеет 4343 теста, и все они проходят. При этом каждое сохранение записи времени отправляет в базу три дополнительных SELECT запроса: ставку самой записи, ставку проекта и ставку активности. Если в одном flush() 50 записей, а столько строк показывает страница массового редактирования, только за ставками уходит 150 запросов. Тесты этот код покрывают, но ни один не падает, в них нет ни одной проверки проблем с запросами к базе данных.

Для решения этой проблемы сделал инструмент, которого в конце августа ещё не существовало. Правда, ещё до проверок сторонних проектов на N+1, он успел несколько раз обмануть меня самого, и всегда одинаково, показывал зелёное там, где на самом деле не работал.

2000 запросов на одну страницу

Когда-то мне пришлось работать с проектом, который вроде бы работал, но на него жаловались, некоторые страницы очень медленно открываются, а сам сервис периодически “подвисает”. Времени на поиски ушло много, а виновником оказалась ленивая загрузка на неограниченном списке в разделе для сотрудников. Одно открытие такой страницы стоило больше 2000 запросов к базе. Если страницу открывали сразу несколько сотрудников, весь сервис фактически “умирал”.

Когда такие места я вычистил, проект на скромных ресурсах спокойно выдерживал нагрузку. Спустя несколько лет, когда я там уже не работал, со мной связался CTO. Он удивлялся, старый проект нагрузку держит, а новый, с кластером базы данных, несколькими серверами приложения и кластером Redis, ту же нагрузку не держит, хотя функционал и количество пользователей практически одинаковое.

Из той истории я вынес неприятное наблюдение, руками отслеживать, какие запросы уходят и в какой последовательности, очень долго, и это не даёт никакой гарантии на будущее, ведь через полгода кто-нибудь добавит в шаблон обращение к ещё одной связи. Ловить такое надо на этапе разработки, а не по баг-репорту от пользователей и просевшей “конверсии”.

Вспомнил я об этом, пока писал статью про VIEW в MySQL и PostgreSQL, где снова пришлось подолгу читать планы запросов. В заметки записал себе, что нужен линтер на PHP, который собирает все SELECT проекта, прогоняет по каждому EXPLAIN и выдаёт ошибки, как PHPStan, только про производительность. Почти всё в этой формулировке потом пришлось поменять.

Готовый пакет показал зелёное

Сначала я проверил и поискал похожие решения. Ближе всего по духу оказался популярный пакет, в виде трейта для PHPUnit со счётчиками запросов, поиском дублей, анализом планов, при этом заявлялась поддержка Laravel и Doctrine. Я поставил его на свой проект (Symfony, Doctrine, PostgreSQL 17) и написал пробный N+1. Пять лотов, у каждого свой тендер, findAll() и обращение к тендеру в цикле.

фаза чтения, запросов: 6
  1) SELECT ... FROM lots t0
  2) SELECT ... FROM tenders t0 WHERE t0.id = ?
  ...
  6) SELECT ... FROM tenders t0 WHERE t0.id = ?
найдено дублей (SQL+байнды совпадают): 0
assertQueriesAreEfficient() на чистом N+1: ПРОШЁЛ
assertNoLazyLoading(): ПРОШЁЛ

Шесть запросов вместо двух, и оба ассерта зелёные. Дубли пакет ищет по совпадению SQL и значений, а у N+1 значения по определению разные. Проверка ленивой загрузки на Doctrine возвращает зелёное, ничего не проверив. Анализ планов на PostgreSQL молча выключается и тоже рапортует зелёным, хотя не разобрал ни одного запроса. Плюс, около 25 строк конфигурации и три строки в setUp() каждого тестового класса.

Потом я повторил проверку на MySQL, где у пакета работает всё, и ошибка поменяла знак. N+1 остался невидимым, потому что план каждого отдельного запроса безупречен: const, PRIMARY, одна строка. Зато на таблице из пяти строк пришёл error: Full table scan, а файл:строка в отчёте указывал внутрь самого пакета.

Пакет, всё же, отвечает на вопрос “сколько запросов делает этот тест”, а мне нужен был другой ответ. Статический анализ вроде phpstan-dba тоже не даёт ответ, так как при использовании ORM, в коде почти не встречается “сырых” запросов, которые phpstan-dba мог бы проанализировать, запросы появляются только при выполнении.

Первую версию я выбросил целиком

Первый проект получился солидным, три пакета, сбор запросов в рантайме с дампом в файл, отдельное PHPStan-правило, которое читает дамп и привязывает находки к коду, плюс хеш и git-ревизия, чтобы дамп не разошёлся с кодом.

Я начал расписывать, зачем нужна каждая часть, и оказалось, что всё держится на одной причине - сбор и анализ разнесены по разным процессам. Если делать всё в одном процессе, прямо во время прогона тестов, стек вызовов живой, файл:строка берётся на месте, а сериализовать и сверять нечего.

Так инструмент стал расширением PHPUnit. В событийной системе PHPUnit 10+ один тест даёт одну трассу, а N+1 можно увидеть только на трассе. Слово “линтер” пришлось убрать, потому что линтер читает код не выполняя, а здесь разбираемся с живым прогоном. EXPLAIN тоже перестал быть основой, потому что главное правило обходится без него. От рабочего названия php-linter-explain в итоге пришлось отказаться, оно не отражало сути, пакет я назвал query-guard.

Есть и ограничение: инструмент видит только то, что покрывают тесты, и непокрытого контроллера для него не существует.

В начале нужно было определить, где открывать трассу. Если в самом начале подготовки теста, в неё попадает setUp(). Фабрика, которая создаёт 50 сущностей в цикле, даёт 50 одинаковых INSERT из одного места, то есть идеальное ложное срабатывание флагманского правила. С таким шумом инструмент не пригоден для использования. Поэтому трасса открывается на событии Test\Prepared, после setUp(), а запросы фикстур копятся отдельно. То что Prepared действительно приходит после setUp(), я проверил тестами, три запроса в setUp(), два в теле теста, и в трассу попадают только два.

Потом был режим strict. Я хотел, чтобы находка роняла тест. Событийная система PHPUnit 10–13 не даёт расширению ни пометить тест упавшим, ни поменять код возврата. Сработал только register_shutdown_function, который выполняется, когда PHPUnit уже закончил работу. В результате PHPUnit печатает OK, а процесс возвращает 1, CI это понимает, человек смотрит на такой вывод с недоумением. Формулировку “находка валит тест” пришлось заменить на “находка валит прогон”.

По той же причине генерация baseline включается не ключом командной строки, а переменной окружения, так как добавить свой ключ к phpunit расширение тоже не может.

EXPLAIN на пустой базе

Сложнее всего было смириться с тем, что EXPLAIN на тестовой базе бесполезен. Мне очень хотелось, чтобы при обычном прогоне тестов EXPLAIN давал адекватную картину, здесь полный перебор, здесь filesort, здесь нет индекса. Но в тестовой базе три фикстурные строки. На трёх строках оптимизатор честно выбирает полный перебор, потому что так дешевле, и план ничего не говорит о том, что будет на проде.Full table scan на пяти строках у готового пакета как раз получился при попытке судить о плане без данных.

Поэтому правила пришлось разделить на два уровня. Первый от объёма данных не зависит и работает сразу: N+1, дубли, запрос в цикле, отсутствие LIMIT, бюджет запросов на тест. Ради этого пакет, в первую очередь, и стоит ставить.

Второй уровень читает планы: table-scan, filesort, temporary-table, no-possible-index. По умолчанию он выключен и включается вместе с указанием базы, где есть объём. Пока в таблице меньше 1000 строк, правила плана молчат. Исключение одно - отсутствие подходящего индекса. Это факт схемы, и на пустой таблице он так же верен.

Разбор планов я делал сразу под MySQL и PostgreSQL, на синтетическом стенде с 100 000 строк. Начни я с одной платформы, в нормализованную модель плана незаметно просочились бы особенности MySQL или PostgreSQL.

Возьмём запрос WHERE plain_col = 42 к таблице на 100 000 строк без индекса на этой колонке. MySQL пишет rows_examined_per_scan: 99989, то есть сколько строк просмотрит. PostgreSQL пишет Plan Rows: 100, то есть сколько вернёт после фильтра. По второму числу о размере таблицы нельзя судить, поэтому для PostgreSQL приходится запрашивать отдельно.

А понятия possible_keys в PostgreSQL нет совсем, и правило no-possible-index там работать не может. Если бы оно просто молчало, я повторил бы ошибку готового пакета, поэтому правило пишет в сводке, что на этой платформе no-possible-index определить не сможет.

Заглушка, которая окупилась в первый же день

Архитектуру я разложил на три независимых направления: ORM-адаптер (как перехватываем запросы), драйвер платформы (как читаем план) и оболочка раннера (откуда берётся граница трассы). Doctrine на PostgreSQL и Eloquent на PostgreSQL используют один разбор плана. Если направления перепутать, появятся классы вида DoctrineMysqlAnalyzer и четыре реализации там, где хватило бы двух.

Первой шла Doctrine: N+1 для неё не ловил ни один инструмент, который я нашёл, и это то, что нужно в первую очередь. Но адаптер под Eloquent я добавил одновременно, и он почти пустой. Проектировать абстракцию под вторую реализацию, которой ещё нет, верный способ наделать ошибок.

Заглушка сломалась на первом живом Laravel. Адаптер проверял method_exists() на listen у DatabaseManager и молча не подписывался, потому что такого метода там нет. DB::listen() работает через магический __call и получает соединение по умолчанию. Правильной точкой подписки оказался диспетчер событий, где одна подписка покрывает все соединения, включая созданные позже.

Второй неожиданный момент, тестовое приложение Laravel создаётся внутри setUp(), так что подписываться в начале подготовки теста рано, фасад там либо пуст, либо смотрит на приложение прошлого теста.

Тесты при этом оставались зелёными, а трасса пустой. Этот тихий отказ я поймал сразу, но __call('listen') потом всплыл ещё раз, на музыкальном проекте.

Первая цифра

Для Doctrine я написал собственный DBAL-middleware, обёртки над Driver, Connection, Statement, и отдельно для DBAL 3 и DBAL 4, потому что у них расходятся сигнатуры exec(), bindValue() и execute(). Штатный логирующий middleware не подошёл, потому что пишет запрос до выполнения, и длительности у него нет.

Само правило N+1 простое, одна форма запроса с вырезанными значениями, одно место в коде, разные значения, не меньше трёх повторов, и только для чтений. Пакетные выборки IN (?, ?, ?) не считаются, ведь это как раз способ лечить N+1.

Контроллерные тесты тайм-трекера: 404 теста, 25 736 запросов, 205 срабатываний в 21 месте кода. Считать важнее места, чинят именно их.

Потом было обогащение для Doctrine. Когда запрос уходит из инициализации ленивой коллекции, в стеке лежит объект PersistentCollection, и по нему известны сущность-владелец и имя поля. Такая находка получает уровень error и называет связь по имени, остальное остаётся эвристикой уровня warning. В Doctrine ORM 3 с нативными ленивыми объектами PHP 8.4 сущности в стеке нет вообще, инициализатор там статическое замыкание, и опознавать приходится по классу кадра. Поддерживаются оба режима. После обогащения срабатываний на том же наборе стало 207, и 14 из них в 7 местах получили имя связи.

Сейчас сводка выглядит так (имена классов и путей заменены):

query-guard
  tests traced: 404, queries: 25736 (in setUp: 0)

  findings: 207

  * [error] n-plus-one — App\Tests\Controller\EntryControllerTest::testExport
    App\Entity\Entry::$tags — lazy-loaded association, 10 queries
    src/Entity/Entry.php:418

  * [warning] n-plus-one — App\Tests\Controller\EntryControllerTest::testSaveRates
    50 queries of the same shape from one place, different values: SELECT ...
    src/Repository/EntryRepository.php:810
      from src/Pricing/RateService.php:96 App\Repository\EntryRepository::findRates
      from src/Controller/EntryController.php:212 App\Pricing\RateService::calculate

Для легаси нужен baseline, иначе первая установка даёт сотни находок, разобрать всё и сразу почти нереально, такой инструмент удалят в тот же день. На “тайм-трекере” 75 срабатываний на 43 тестах свернулись в 24 подписи, повторный прогон прошёл чисто, а strict без baseline вернул 1. Подпись - это правило, файл и форма запроса, без номера строки и без имени теста. Номер строки меняется от любой правки выше по файлу, имя теста от переименования, и то и другое обнуляло бы baseline.

Семь чужих проектов

Я набрал open-source проекты с живыми тестовыми наборами и разными стеками. Три способа маппинга Doctrine (атрибуты, XML и ClassMetadataBuilder), DBAL 3 и 4, MySQL, MariaDB, PostgreSQL и SQLite, голый PHPUnit и Pest. Схема везде одна, поставить пакет, прогнать чужие тесты как есть и довести находки до продакшен-кода.

CMS: я назвал не того виновника

CMS держит в репозитории готовые окружения под MySQL, MariaDB и PostgreSQL, я прогнал плагин на всех трёх, вердикты совпали.

Нашлась одна подтверждённая ленивая загрузка, коллекция версий файла у медиа. Отчёт показывал только место, откуда ушёл запрос, а это геттер сущности, который вызывают отовсюду. Кто вызвал его в этот раз, отчёт не говорил, и я додумал сам. Раз геттер медиа, решил я, то виноват код, который отдаёт медиа через API. В issue так и написал, N+1 возникает, когда API читает список медиа.

Мейнтейнер возразил по делу. При чтении медиа нужная версия файла подтягивается тем же запросом через JOIN, так что никакой отдельной загрузки там быть не может, и где тогда реальный случай? Я перепрогнал тесты, на этот раз сохраняя полный стек каждого запроса. Код, который отдаёт медиа через API, не встретился ни в одном стеке. Все ленивые загрузки случались не при чтении, а при сохранении. Когда PATCH-запрос добавляет или убирает медиа у контакта, на каждое такое медиа создаётся событие для журнала активности, и каждое событие отдельным запросом загружает версии файла. Два добавленных и два удалённых медиа дают четыре запроса. Проблема оказалась мельче, чем я описал, и совсем в другом месте.

Из-за этой ошибки появились строки from в сводке, то есть цепочка вызывающих перед самим запросом.

Тайм-трекер: откуда 150 запросов

Весь набор, 4343 теста и 38 103 запроса, 1182 срабатывания в 84 местах, из них 9 мест с подтверждённой ленивой загрузкой. Опыт CMS я сразу учёл, ни одна находка не описана по месту запроса, под каждой полный стек. Три дошли до продакшен-кода, по каждой я завёл issue.

Самая крупная из них - пересчёт ставок из начала статьи, и на ней стек снова пригодился. Самые большие счётчики в отчёте, по 50 повторов, пришлись на фикстуру, которая создаёт 50 записей одним flush(). По одним этим цифрам находка выглядела артефактом тестов. Пришлось отдельно замерить продакшен-путь массового сохранения:

Ровно 4N + 5, один INSERT и три SELECT ставок на запись, на 50 записях это 205 запросов. Схематично:

// подписчик на onFlush
foreach ($scheduledEntries as $entry) {
    $this->rateService->calculate($entry); // внутри три отдельных SELECT
}

Внутри одного flush() ставки не меняются, поэтому в issue я предложил кеш на время запроса.

Интернет-магазин на Pest: зелёный и пустой

Проект на Laravel, Pest, имеет 1477 тестов, прогон тестов зелёный, но файл отчёта не появился, и в консоли от query-guard не было ни строчки.

Первая мысль, плагин не запустился, что-то ему помешало, надо смотреть логи. В логах про падение ничего. Значит, надо копать дальше.

Я вставил file_put_contents первой строкой в bootstrap() расширения. Файл появился, значит, расширение загружалось, но следующей же строкой выходило. Pest всегда добавляет к аргументам PHPUnit --no-output, потому что печатает сам, через Collision. А у меня стоял ранний выход по $configuration->noOutput(), приём, подсмотренный у хорошего расширения для поиска медленных тестов. Для PHPUnit этот флаг значит “пользователь попросил тишины”, для Pest “печатаем не PHPUnit”. Мой код читал второе как первое.

Пользователь Pest ставил пакет по README и получал молчание, которое не отличить от “находок нет”, то есть ровно то, что я хотел избежать.

С локальным обходом этого условия прогон дал 158 214 запросов и 12 813 срабатываний в 742 местах, по времени примерно как без расширения, 424 секунды против 430. Там же вскрылся второй тихий отказ. Под pest --parallel каждый воркер ParaTest писал отчёт в один и тот же файл и затирал соседей. На выборке из 34 тестов в отчёте оставалось 7, остальные 79% пропадали молча.

Из 12 813 срабатываний разбор стека и воспроизведение без инструмента подтвердили две настоящие проблемы: около десяти запросов на каждую позицию корзины в каждом ответе API корзины и чтение схемы таблицы из information_schema при каждом сохранении товара.

Повторный прогон на исправленной версии, уже с цепочкой вызовов, нашёл ещё две. Одну из них первый прогон прямо записал в “проверено, не является находкой”, потому что, судя по тесту, товары создавала фикстура, но, оказалось, что и сам обработчик события в прод-коде устроен так же.

Музыкальный сервер: 1611 предупреждений на 1612 тестов

Проект на Laravel, голый PHPUnit, SQLite в памяти, первый прогон:

OK, but there were issues!
Tests: 1612, Assertions: 11785, PHPUnit Warnings: 1611.

Exception in third-party event subscriber: Target class [config] does not exist.

Снова виновник __call('listen'), Laravel в tearDown() вычищает контейнер, но фасад до setUp()следующего теста продолжает смотреть на DatabaseManager прошлого. Адаптер спрашивал is_callable([$manager, 'listen']) и получал true, потому что у менеджера есть __call. Вызов уходил в пустой контейнер и падал. На заглушке этот магический метод заставил адаптер молча не подписаться, здесь он же ронял подписку на каждом тесте.

Неприятнее всего было перепроверить CRM на Pest, где я запускал инструмент незадолго до этого. Там всё это время сыпались те же исключения, по одному на тест. PHPUnit ставит счётчик в подвал и меняет OK на OK, but there were issues!. Pest печатает одну строку WARN в общем потоке, без счётчика и без изменения итога. Среди 42 тестов она затерялась, и я её пропустил. На чужом наборе мало смотреть на цвет, надо читать “подвал”.

Там же, на музыкальном сервисе, попалась находка другого рода. Самым крупным кластером отчёта оказался N+1 в сканере медиатеки, который в проде невозможен. В проде результат поиска артиста кешируется, а под тестом кеширование намеренно выключено. Трасса была верной, просто описывала алгоритм, который на проде не работает.

Почему молчание хуже падения

Упавший инструмент чинят в тот же день. Промолчавший удаляют через месяц со словами “ничего полезного не нашёл”, и никто так и не узнаёт, что он просто не работал.

После прогонов главное правило пакета такое: зелёный отчёт и “мы не смотрели” не должны выглядеть одинаково. Сводка информирует, если ORM не найден или перехват не встал, если за весь прогон не пришло ни одного запроса, если правило плана на этой платформе не может отработать, если треть находок указывает внутрь vendor/ или на фикстуры, если baseline снят на другой СУБД.

Под параллельным раннером каждый воркер пишет свой файл отчёта, иначе двенадцать воркеров оставили бы в файле только часть того, кто закрылся последним. Генерировать baseline под ParaTest расширение отказывается явно.

Что вышло в итоге

Требования: PHP 8.2+, PHPUnit 10.5–13, Doctrine ORM 2–3 с DBAL 3–4 или Laravel 11+, MySQL или MariaDB или PostgreSQL. Цена на запрос внутри теста при включённом плагине около 0,006 мс (0,15 секунды на 25 000 запросов) и примерно 0,5 МБ памяти на тысячу запросов.

Инструмент видит только то, что запрашивается в тестах. Правилам второго уровня, которые читают EXPLAIN, нужна заполненная база. На трёх фикстурных строках план показывает, как оптимизатор обходится с почти пустой таблицей, а не что будет под нагрузкой, поэтому на маленьких таблицах эти правила молчат.

Сводка в консоли написана для человека, и её формулировки могут меняться. Для автоматики есть JSON-отчёт (report-json), у него есть версия формата отчёта, которая растёт только при несовместимых изменениях, пути относительно корня проекта и поле failing с ответом на главный вопрос CI-скрипта, упадёт ли прогон. Такой файл читают без разбора текста, и сделать это может и пайплайн, и бот, который комментирует pull request.

Всё больше код пишут нейросети, и N+1 проскакивает у них легко, сгенерированный контроллер обходит список сущностей и в цикле через связь запрашивает данные, тест на ответ проходит, а в диффе на ревью последовательности запросов не видно. Её нельзя увидеть, читая код, и нейросеть, которая этот код написала, её тоже не видит. Чем больше кода приходит таким путём, тем меньше можно полагаться на внимательное ревью и тем больше на проверки, которые запускаются сами: линтеры, статический анализ, тесты. Пакет query-guard добавляет к ним взгляд на запросы, которые код действительно сделал. А JSON-отчёт с местом в коде и цепочкой вызовов можно вернуть той же нейросети вместе с задачей на исправление.