Profiling before you optimise

Two days went into rewriting the price calculation, which everybody agreed was the slow part of the product page. It went from 180 milliseconds to 40, and the page got 12 milliseconds faster — because the calculation ran once and something nobody had looked at ran four hundred times.

The symptom

$ curl -s -o /dev/null -w '%{time_total}n' 
    'https://staging/products/8814'
1.412

# and the theory, which everybody held:
#   "the price calculation. it does a lot of work."

# after two days:
$ curl -s -o /dev/null -w '%{time_total}n' 
    'https://staging/products/8814'
1.400

The rewrite was real and the improvement was real and neither mattered, because the function was three per cent of the request. Nobody had measured which three per cent.

Why it happens

A function that looks expensive attracts attention, and a function that is called four hundred times from inside a loop in a template does not — it looks like one line. Intuition about performance is anchored on how complicated code looks, and cost is a function of how often it runs.

The fix

A profile, which takes ninety seconds to get

$ php -d xdebug.mode=profile 
     -d xdebug.output_dir=/tmp/prof 
     -d xdebug.start_with_request=trigger 
     -S 127.0.0.1:8080 -t public

$ curl 'http://127.0.0.1:8080/products/8814?XDEBUG_TRIGGER=1'
$ ls /tmp/prof/
cachegrind.out.14022

The trigger mode is what makes this usable: profiling every request produces gigabytes and slows everything by a factor of five, so profiling only the request with the parameter is the difference between a tool and an ordeal.

Xdebug 3 changed the configuration entirely — xdebug.mode replaced half a dozen separate flags — and most of the documentation still describes the 2.x names, which is worth knowing before spending twenty minutes on why nothing is written.

$ kcachegrind /tmp/prof/cachegrind.out.14022

Incl.   Self    Called   Function
98.2%   0.1%          1   {main}
71.4%   2.1%        412   Product::currentStock
68.9%   1.4%        412   StockRepository::forVariant
64.2%   61.8%       412   PDO::query
 3.1%   2.9%          1   PriceCalculator::calculate

412 calls. one per variant. each one a query.

The distinction between inclusive and self cost is the whole skill of reading a profile: currentStock has 71% inclusive and 2% self, which means it is not slow — it calls something slow, four hundred and twelve times. Sorting by self cost finds where the time is spent and sorting by inclusive finds who is responsible.

The other two profilers, and when each is right

Xdebug        exact call counts, every function. and a
              5-10x slowdown, so: local and staging only.
              → "what is this request doing"

tideways_xhprof  sampling, ~2% overhead, safe in production
              on a fraction of requests.
              → "what is slow for real users"

EXPLAIN + the   the queries, which is where the time
slow query log  usually is anyway. free.
              → start here, actually

The slow query log is the one to check first because it costs nothing and it is right most of the time. Four hundred and twelve queries of two milliseconds each do not appear in it — each is below any sensible threshold — which is exactly the case where a profiler earns its keep.

// and the cheapest instrument of all, which finds N+1
// without any extension at all
DB::listen(function ($query) {
    $GLOBALS['q'][] = $query->sql;
});

register_shutdown_function(function () {
    $counts = array_count_values($GLOBALS['q'] ?? []);
    arsort($counts);

    foreach (array_slice($counts, 0, 5, true) as $sql => $n) {
        if ($n > 10) {
            error_log("{$n}x {$sql}");
        }
    }
});

Counting identical query strings and reporting the repeats is fifteen lines and catches the single most common performance bug in any ORM application. It works because an N+1 produces the same SQL with different bindings, so grouping by the statement rather than the full query is what makes the pattern visible.

The actual fix, which was one line

// the template, which nobody considered part of the code
@foreach ($product->variants as $variant)
    {{ $variant->currentStock() }}    {{-- a query. each. --}}
@endforeach

// the controller
$product = Product::with('variants.stock')->findOrFail($id);

// 412 queries → 2

Eager loading is the fix in almost every case and the reason it was not applied is that nothing pointed at the template. The profile pointed at PDO::query and the call count pointed at the loop, and the two together made a two-day investigation into a ten-minute one.

$ curl -s -o /dev/null -w '%{time_total}n' 
    'https://staging/products/8814'
0.196          # 1.412 → 0.196

Where to measure, which is not where it hurts

profiling on a laptop finds the wrong things:

  the database is local        → queries look 10x cheaper
  opcache may be off           → autoloading dominates
  the dataset is a fixture     → 40 rows, not 400,000
  one request at a time        → no lock contention

so: profile on staging with a production-sized dataset, or
sample in production. a laptop profile is a hypothesis.

The dataset size is the one that inverts conclusions rather than merely scaling them. A query without an index is instant on forty rows and is the entire request on four hundred thousand, so a laptop profile can rank a missing index below a function that is genuinely irrelevant.

The opcache point is worth checking before drawing any conclusion at all: with it off, class loading and compilation can be a third of the profile, which sends people optimising an autoloader that costs nothing in production.

Verifying it worked

$ php -d xdebug.mode=profile ... && kcachegrind ...

Incl.   Self    Called   Function
42.1%   38.4%        2   PDO::query
11.2%   10.8%        1   PriceCalculator::calculate

# 412 calls → 2, and the calculation is now 11% of a
# much smaller number.

# and the regression guard, in the test suite
$ vendor/bin/phpunit --filter QueryCountTest
Tests: 14 passed

public function testProductPageDoesNotNPlusOne(): void
{
    DB::enableQueryLog();

    $this->get('/products/' . $this->productWithVariants(50)->id)
        ->assertOk();

    $this->assertLessThan(10, count(DB::getQueryLog()));
}

Asserting a query-count bound with a fixture that has fifty variants is what stops the N+1 coming back, and the number should be a loose bound rather than an exact count — a test asserting exactly seven queries fails on every unrelated change and gets deleted.

The calculation being 11% of the profile afterwards is the useful epilogue: it was three per cent of a slow request and is eleven per cent of a fast one, which means the two days of work would now be worth doing. Optimising in the right order is the whole point rather than optimising the right thing once.

What this costs

An extension in the development image, a staging environment with a realistic dataset, and the discipline to spend ninety seconds measuring when the answer feels obvious. The last one is the expensive part — the profile in this case confirmed nothing anybody believed, which is precisely why it was worth running and precisely why it had not been.

The query-count test is the piece that keeps working after the investigation is forgotten, and it has a real weakness: it asserts a count rather than a duration, so a change that replaces four hundred fast queries with two slow ones passes. That is usually the right trade and it is worth knowing that the test is a proxy rather than a measurement.