DEV Community

Cover image for Tests green, queries not: what building an N+1 detector for PHPUnit taught me
Aleksander Frolov
Aleksander Frolov

Posted on Originally published at frolov.guru

Tests green, queries not: what building an N+1 detector for PHPUnit taught me

An open-source time tracker built on Symfony has 4343 tests, and every one of them passes. Yet each time entry it saves sends three extra SELECT queries to the database: the rate of the entry itself, the rate of the project, and the rate of the activity. With 50 entries in one flush(), which is exactly how many rows the bulk edit page shows, the rates alone cost 150 queries. The tests cover this code, and none of them fails: not one of them checks for problems with database queries.

To solve this problem, I built query-guard, a PHPUnit extension. Before it ever looked for N+1 in other people's projects, though, it managed to fool me several times, and always the same way: it showed green where it was not working at all.

A ready-made package said green

First I looked for existing solutions. The closest in spirit was a popular package: a PHPUnit trait with query counters, duplicate detection, and plan analysis, advertised as supporting Laravel and Doctrine. I installed it on my own project (Symfony, Doctrine, PostgreSQL 17) and wrote a trial N+1: five lots, each with its own tender, findAll() and a read of the tender in a loop.

read phase, queries: 6
  1) SELECT ... FROM lots t0
  2) SELECT ... FROM tenders t0 WHERE t0.id = ?
  ...
  6) SELECT ... FROM tenders t0 WHERE t0.id = ?
duplicates found (SQL + bindings match): 0
assertQueriesAreEfficient() on a plain N+1: PASSED
assertNoLazyLoading(): PASSED
Enter fullscreen mode Exit fullscreen mode

Six queries instead of two, and both assertions green. The package looks for duplicates by matching SQL and values, and in an N+1 the values differ by definition. The lazy loading check returns green on Doctrine without checking anything. Plan analysis on PostgreSQL switches itself off silently and also reports green, even though it has not parsed a single query.

Six queries of a textbook N+1 and three checks: EXPLAIN and duplicate detection pass, query shape plus place in code reveals the N+1

Then I repeated the check on MySQL, where everything in the package works, and the error flipped sign. The N+1 stayed invisible, because the plan of each individual query is flawless: const, PRIMARY, one row. Instead, a table of five rows got error: Full table scan, and the file:line in the report pointed inside the package itself.

Static analysis such as phpstan-dba does not give the answer either: with an ORM, the code contains almost no "raw" queries for phpstan-dba to analyze, and the queries only appear at runtime.

One process, one trace

The first design came out impressive: three packages, runtime query collection with a dump to a file, a separate PHPStan rule that reads the dump and maps findings to code, plus a hash and a git revision so that the dump would not drift away from the code.

Everything rested on a single reason: collection and analysis lived in different processes. If you do everything in one process, right during the test run, the call stack is alive, file:line is available on the spot, and there is nothing to serialize or reconcile.

That is how the tool became a PHPUnit extension. In the PHPUnit 10+ event system one test gives one trace, and N+1 can only be seen in a trace. There is a limitation as well: the tool sees only what the tests cover.

PHPUnit events: setUp() queries are kept aside, the trace opens on Test\Prepared, and in strict mode PHPUnit prints OK while the process exits with 1

The first thing to decide was where to open the trace. If it opens at the very start of test preparation, setUp() ends up inside it, and a factory that creates 50 entities in a loop produces 50 identical INSERTs from one place, a perfect false positive. So the trace opens on the Test\Prepared event, after setUp(), and fixture queries are collected separately.

Then came strict mode. I wanted a finding to fail the test. The PHPUnit 10–13 event system lets an extension neither mark a test as failed nor change the exit code. The only thing that worked was register_shutdown_function, which runs after PHPUnit has finished. As a result PHPUnit prints OK while the process exits with 1. CI understands that; a human stares at the output in confusion.

EXPLAIN on an empty database

The hardest thing to accept was that EXPLAIN on a test database is useless. A test database holds three fixture rows. With three rows the optimizer honestly picks a full scan because it is cheaper, and the plan tells you nothing about production.

So the rules had to be split into two tiers. The first tier does not depend on data volume and works right away: N+1, duplicates, queries in a loop, a missing LIMIT, a query budget per test. The second tier reads plans (table-scan, filesort, temporary-table, no-possible-index); it is off by default and turns on together with a pointer to a database that has real volume.

The N+1 rule

The rule itself is simple: one query shape with the values stripped out, one place in the code, different values, at least three repeats, and reads only. Batched lookups with IN (?, ?, ?) do not count, since that is exactly how N+1 gets fixed. For Doctrine, a lazy collection being initialized leaves a PersistentCollection in the stack, so such a finding gets the error level and names the association.

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
Enter fullscreen mode Exit fullscreen mode

(Class names and paths replaced.) A legacy project needs a baseline, otherwise the first install produces hundreds of findings and the tool gets removed the same day. On the time tracker, 75 hits across 43 tests collapsed into 24 signatures, and the rerun came out clean.

Seven projects that were not mine

The CMS: I blamed the wrong code

There was one confirmed lazy load: the collection of file versions on a media item. The report showed only the place the query came from, an entity getter called from everywhere, so I filled in the gap myself and wrote in the issue that the N+1 happens when the API reads a list of media.

The maintainer objected, and with good reason: on read, the needed file version is fetched by the same query through a JOIN. I reran the tests, saving the full stack of every query. Every lazy load happened on save, not on read: a PATCH request that adds or removes media on a contact creates an activity log event for each item, and each event loads the file versions with a query of its own.

My guess in the issue is crossed out; in fact a contact PATCH creates an activity-log event per media item, and each loads file versions

That mistake is why the summary now has from lines: the chain of callers leading up to the query.

The time tracker: where 150 queries come from

The full suite, 4343 tests and 38,103 queries: 1182 hits in 84 places, 9 of them with confirmed lazy loading. Three made it down to production code, and I filed an issue for each. The largest counters came from a fixture, so I measured the production bulk save path separately:

Entries in one flush() Queries
1 7
5 25
10 45
25 105

Exactly 4N + 5: one INSERT and three rate SELECTs per entry. Schematically:

// onFlush subscriber
foreach ($scheduledEntries as $entry) {
    $this->rateService->calculate($entry); // three separate SELECTs inside
}
Enter fullscreen mode Exit fullscreen mode

The online store on Pest: green and empty

A Laravel project on Pest with 1477 tests. The run was green, but no report file appeared, and query-guard printed not a single line. I put file_put_contents on the first line of the extension's bootstrap(). The file appeared, so the extension was loading, but it quit on the very next line. Pest always adds --no-output to the PHPUnit arguments, because it prints the output itself through Collision, and I had an early return on $configuration->noOutput(). For PHPUnit that flag means "the user asked for silence"; for Pest it means "PHPUnit is not the one printing".

The same run exposed a second silent failure: under pest --parallel every ParaTest worker wrote its report to the same file, and on a sample of 34 tests the report kept 7.

The music server: 1611 warnings for 1612 tests

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

Laravel empties the container in tearDown(), but until the next test's setUp() the facade keeps pointing at the previous test's DatabaseManager. The adapter asked is_callable([$manager, 'listen']) and got true, because the manager has __call. The call went into an empty container. Rechecking the CRM on Pest showed the same exceptions there all along: Pest prints a single WARN line with no counter, and among 42 tests I missed it.

Why silence is worse than a crash

Four silent failures: the Eloquent stub, Pest and --no-output, ParaTest and a shared report file, Laravel exceptions between tests

A tool that crashes gets fixed the same day. A tool that stays silent gets removed a month later with "it never found anything useful", and nobody ever learns that it simply was not working.

So the package's main rule is this: a green report and "we did not look" must not look the same. The summary tells you when no ORM was found or interception did not start, when not a single query arrived, when a plan rule cannot work on this platform, and when a third of the findings point into vendor/ or at fixtures.

Try it

Requirements: PHP 8.2+, PHPUnit 10.5–13, Doctrine ORM 2–3 with DBAL 3–4 or Laravel 11+. The cost per query inside a test is about 0.006 ms and roughly 0.5 MB of memory per thousand queries.

composer require --dev alex-frolov/query-guard
Enter fullscreen mode Exit fullscreen mode

The phpunit.xml wiring and the Doctrine setup are in the README. Look past the color of the run and read the summary: how many tests were traced, how many queries, and which three places top the list.

The full story, with plan parsing on MySQL and PostgreSQL and the JSON report for CI: frolov.guru/en/writing/query-guard-n-plus-one.


I'm Aleksander Frolov, a senior/staff backend engineer building highload PHP systems. I write about architecture and performance on frolov.guru.

Top comments (0)