Measuring Before Optimising

Take a baseline, load test one route at a time, and read p95 rather than the mean: the slow part is rarely where you guess.

SyntaxBenchmark::measure(Closure|array $benchmarkables, int $iterations = 1): array|float

Optimising without a measurement is rewriting code at random. A baseline is a number you wrote down before the change, taken the same way afterwards. Without one, "it feels faster" is all you have.

Measure the request, not your impression

Three levels, cheapest first. A middleware that times $next($request) gives a duration per route in the log. DB::listen() counts the queries inside that duration. DB::whenQueryingForLongerThan(500, $callback) fires when a single request spends more than 500ms in the database, which tells a slow database apart from slow PHP.

For one suspect block, Illuminate\Support\Benchmark::measure($callback, iterations: 10) returns the average milliseconds, and Benchmark::dd() prints and stops.

Load test one route

A single request tells you little. Send many at once: ab -n 2000 -c 50 https://staging.example.com/api/orders, or the same with k6 or wrk. Test something shaped like production: php artisan optimize run, APP_DEBUG=false, Telescope and Debugbar absent, and realistic row counts. An empty table makes every query look fast.

Read percentiles

The mean hides the tail. Report p50 and p95 together: one request in twenty at 410ms is a real complaint that a mean of 124ms conceals. Record queries per request next to them, because that is the number a fix usually moves.

Example

Try it yourself
Loading editor…
Press Run to execute the code.

When to use it

  • Writing a before-and-after number into a pull request that claims a speedup.
  • Deciding whether the database or PHP is the bottleneck on one slow endpoint.
  • Finding the route with the worst p95 before choosing what to cache.
  • Confirming that a cache you added actually removed the queries.

More examples

A duration per route in the log

Generated by php artisan make:middleware MeasureRequestDuration and registered globally in bootstrap/app.php with $middleware->append(MeasureRequestDuration::class) inside the withMiddleware() closure. Timing around $next($request) covers routing, the controller and the response, but not framework bootstrap. public/index.php defines LARAVEL_START with microtime(true) before anything boots, so comparing against that constant includes bootstrap too - but it is defined once per PHP process, which is once per request only under the usual one-process-per-request setup. A week of these log lines is what makes a p95 possible.

Example · php
<?php

// app/Http/Middleware/MeasureRequestDuration.php

declare(strict_types=1);

namespace App\Http\Middleware;

use Closure;
use Illuminate\Http\Request;
use Illuminate\Support\Facades\Log;
use Symfony\Component\HttpFoundation\Response;

class MeasureRequestDuration
{
    public function handle(Request $request, Closure $next): Response
    {
        $start = microtime(true);

        $response = $next($request);

        Log::info('request.duration', [
            'route' => $request->route()?->getName() ?? $request->path(),
            'ms' => round((microtime(true) - $start) * 1000, 1),
            'status' => $response->getStatusCode(),
        ]);

        return $response;
    }
}

Which queries, and how long in total

These two answer different questions. DB::listen catches the single expensive query; whenQueryingForLongerThan catches the request that ran two hundred cheap ones, which is the shape an N+1 has. Both fire in production, where the slow route actually lives, and both are honest about where the time went: if a 900ms request shows 40ms of database time, the remaining 860ms is PHP and no index will help it.

Example · php
<?php

// app/Providers/AppServiceProvider.php

declare(strict_types=1);

namespace App\Providers;

use Illuminate\Database\Connection;
use Illuminate\Database\Events\QueryExecuted;
use Illuminate\Support\Facades\DB;
use Illuminate\Support\Facades\Log;
use Illuminate\Support\ServiceProvider;

class AppServiceProvider extends ServiceProvider
{
    public function boot(): void
    {
        // One query took too long.
        DB::listen(function (QueryExecuted $query): void {
            if ($query->time > 100) {
                Log::warning('slow query', [
                    'ms' => $query->time,
                    'sql' => $query->toRawSql(),
                ]);
            }
        });

        // One request spent too long querying, however it was split up.
        DB::whenQueryingForLongerThan(500, function (Connection $connection, QueryExecuted $event): void {
            Log::warning('over 500ms querying '.$connection->getName());
        });
    }
}

The before and after numbers

Run the test twice and discard the first run: caches, opcache and the database's own buffers make a cold run unrepresentative. Change one thing between measurements, or you will not know which change paid. Keep the numbers in the pull request - a claim of "faster" that nobody can reproduce is the reason the next person optimises the same route again. php artisan optimize:clear undoes the caching afterwards.

Example · shell
# Make the target look like production before timing it.
php artisan optimize          # config, events, routes and views cached

# 2000 requests, 50 at a time, against a real web server.
ab -n 2000 -c 50 -H 'Accept: application/json' \
   https://staging.example.com/api/orders

# What goes in the pull request:
#   before   p50  91ms   p95 410ms   queries/req 38
#   after    p50  44ms   p95  61ms   queries/req  3

Related

laravel debugbar telescopelaravel n plus onelaravel query performancelaravel octanelaravel deploy monitoring

Discussion

  • Be the first to comment on this lesson.