Finding the 200 milliseconds nobody could account for

The application’s own timing said 140 milliseconds. The browser said 340. Nobody could explain the gap, and because the framework’s debug bar showed a number everyone was comfortable with, it had gone unexamined for a year.

The symptom

$ curl -w 'ttfb:%{time_starttransfer} total:%{time_total}n' -o /dev/null -s https://shop.example.com/products
ttfb:0.341 total:0.352

# and the application's own log line for the same request
[2016-03-08 11:22:41] request.INFO: GET /products {"duration_ms":139}

Two hundred milliseconds spent somewhere neither number covered.

Why it happens

Application timing starts when the application starts timing, which is after the interpreter has booted, the autoloader has been registered and the framework has assembled itself. Everything before that first call is invisible by construction — the measurement cannot see its own setup.

That is fine as a relative measure and misleading as an absolute one, because the two numbers get compared against each other in exactly the situation where the difference matters.

The fix

Measure from the first byte the server saw

nginx knows when the request arrived and when the response finished, and PHP-FPM knows when it received the request. Both numbers are available and neither is in the application.

log_format timed '$remote_addr "$request" $status '
                 'req=$request_time upstream=$upstream_response_time';

access_log /var/log/nginx/access.log timed;

$request_time is the whole thing including reading the request and writing the response; $upstream_response_time is what PHP-FPM took. The difference between the two is nginx and the network. The difference between $upstream_response_time and the application’s own figure is the boot.

203.0.113.9 "GET /products" 200 req=0.338 upstream=0.334

# so: nginx 4ms, php-fpm 334ms, application 139ms
# 195ms is happening inside PHP and outside the application

Then instrument the boot itself

PHP records when the request began, before any of your code runs. Comparing against it from the earliest line of the front controller gives the number the framework cannot.

// public/index.php, first line
$bootStart = microtime(true);
$requestStart = $_SERVER['REQUEST_TIME_FLOAT'];

require __DIR__ . '/../vendor/autoload.php';
$afterAutoload = microtime(true);

$app = require __DIR__ . '/../bootstrap/app.php';
$afterBoot = microtime(true);

header(sprintf(
    'Server-Timing: pre=%.1f, autoload=%.1f, boot=%.1f',
    ($bootStart - $requestStart) * 1000,
    ($afterAutoload - $bootStart) * 1000,
    ($afterBoot - $afterAutoload) * 1000
));

Server-Timing: pre=2.1, autoload=118.4, boot=71.9

118 milliseconds in the autoloader. That is not a framework problem and it is not application code; it is the filesystem being asked the same questions several hundred times per request.

What it turned out to be

Two things, both configuration rather than code. The autoloader was unoptimised, so PSR-4 was resolving each of roughly four hundred classes with filesystem checks. And OPcache was revalidating timestamps on every file on every request, which is correct in development and pure overhead on a server where files only change during a deploy.

; production
opcache.validate_timestamps=0    ; and the deploy must reset the cache
opcache.max_accelerated_files=10000
opcache.memory_consumption=128

$ composer dump-autoload --optimize --classmap-authoritative
Generating optimized autoload files

# and, because validate_timestamps is now off:
$ systemctl reload php7.0-fpm

Verifying it worked

203.0.113.9 "GET /products" 200 req=0.152 upstream=0.148

Server-Timing: pre=2.0, autoload=3.1, boot=4.8

The autoloader went from 118 milliseconds to 3, and the parts now add up: 148 upstream against 139 of application work leaves nine milliseconds of boot, which is a number that can be reasoned about rather than a gap.

The other 70 milliseconds, which was DNS

Autoloading explained 118 of the 195 milliseconds. The remaining 72 sat in the boot phase and did not look like anything — until the same measurement was taken with the internal resolver unreachable and the number changed shape entirely.

// config/services.php, evaluated on every boot
return array(
    'search' => array(
        // a hostname, resolved by the client in its constructor
        'host' => env('SEARCH_HOST', 'search.internal.example.com'),
    ),
);

A service provider was constructing the search client eagerly, and the client resolved its hostname on construction. The internal resolver answered in about 70 milliseconds, on every request, for a client that most pages never used.

Binding it lazily is the fix, and it is one line — the container builds nothing until something asks:

$this->app->singleton(SearchClient::class, function () {
    return new SearchClient(config('services.search.host'));
});

Installing a local caching resolver was the first suggestion and would have taken the lookup under a millisecond, which is to say it would have hidden the problem rather than fixed it — leaving an eagerly-constructed dependency in the boot path for whoever profiled it next.

Keeping the measurement after the fix

A one-off investigation answers today’s question and does nothing about the next boot-time dependency somebody adds. The instrumentation is three lines and is worth leaving in permanently, gated so it costs nothing for ordinary visitors.

// only for staff, or with an explicit header
$show = isset($_SERVER['HTTP_X_TIMING']) && hash_equals(
    getenv('TIMING_TOKEN'),
    $_SERVER['HTTP_X_TIMING']
);

if ($show) {
    header(sprintf('Server-Timing: pre=%.1f, autoload=%.1f, boot=%.1f', ...));
}

The token check rather than a role check, because the interesting measurement is of an anonymous request — logging in changes the boot path and hides exactly what you came to look at.

The other half is an alert on the gap rather than on the absolute number. Boot time is stable and creeps: a provider added here, a config file there. A check comparing $upstream_response_time against the application’s own figure catches the creep at the point it starts, which is considerably cheaper than another afternoon like this one.

What this costs

The instrumentation stays, and it is not free — three microtime() calls and a header per request is negligible, but the Server-Timing header exposes internal structure to anyone who looks. Restricting it to authenticated staff or to a request header is worth the extra condition.

The larger cost is that validate_timestamps=0 makes the deploy responsible for something it was not before. A deploy that fails to reload FPM now leaves the site running old code with no visible symptom, which is a worse failure than a slow autoloader. It needs a check in the pipeline that the running version is the deployed one.