4343 зелёных теста и 150 лишних запросов: как я делал детектор N+1 для PHPUnit

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

Для легаси нужен baseline, иначе первая установка даёт сотни находок, разобрать всё и сразу почти нереально, такой инструмент удалят в тот же день. На «тайм-трекере» 75 срабатываний на 43 тестах свернулись в 24 подписи, повторный прогон прошёл чисто.

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

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

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

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

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

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

Ровно 4N + 5, один INSERT и три SELECT ставок на запись, на 50 записях это 205 запросов. Внутри одного flush() ставки не меняются, поэтому в issue я предложил кеш на время запроса.

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

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

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

Там же вскрылся второй тихий отказ. Под pest --parallel каждый воркер ParaTest писал отчёт в один и тот же файл и затирал соседей. На выборке из 34 тестов в отчёте оставалось 7, остальные 79% пропадали молча.

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

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

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

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

Требования: 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 МБ памяти на тысячу запросов.

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

Полная версия с разбором планов MySQL и PostgreSQL, режимом strict, baseline и схемами — на frolov.guru. Пакет: github.com/alex-frolov/query-guard, установка composer require --dev alex-frolov/query-guard.

Автор: Александр Фролов · Senior/Staff Backend Engineer · PHP Highload · Symfony · Architecture · Team Lead · frolov.guru