ICanBoogie already collects timing information about its time-sensitive components, but I had no good way to look at it for API requests. In this article, we will see how the Server-Timing HTTP header solves that, how the feature is built to respect the dependencies between packages, and how to read the result in the browser.

What I had

ICanBoogie has telemetry on its time-sensitive components:

  • ConfigProfiler records how long each configuration takes to build;
  • EventProfiler records every listener call, and the events that were emitted with no listener at all;
  • ActiveRecord connections record every statement they execute, with its duration.

Until now, I rendered that information as an HTML comment at the top of the page. It worked, but it only works for pages. An API request returns JSON, and there is no place for a comment in JSON, yet those are the requests my Vue application makes.

What Server-Timing is

Server-Timing is a response header: a comma-separated list of metrics, each with a name, an optional duration in milliseconds, and an optional description.

Server-Timing: app;dur=334.42, config;dur=47.72;desc="6 configs"

Browsers display the metrics in the network panel of their developer tools, and JavaScript can read them with the serverTiming property of the performance entries. It works for pages, for API requests, for images, for anything with a response. The header is readable by any client, and by other origins when Timing-Allow-Origin is set. It reveals timings and counts about the internals of the application. I consider it a development and staging feature and not something to enable in production.

Where the code goes

My first idea was to have the telemetry classes produce the metrics, but I didn't want to have http as a dependency where it doesn't belong. ICanBoogie already has a place that sees everything: the bind-* packages. They automatically wire standalone packages to ICanBoogie.

I wrote the decision down in an ADR, this is the short version:

  • icanboogie defines an interface, ServerTimingProvider, and runs the providers;
  • each bind-* package ships a provider that adapts the telemetry of its package;
  • the telemetry packages don't change.

The implementation

The interface

<?php

namespace ICanBoogie;

use ICanBoogie\HTTP\Headers\ServerTiming;

interface ServerTimingProvider
{
    /**
     * Adds metrics to the timing of the response.
     */
    public function alter(ServerTiming $timing): void;
}

ServerTiming and ServerTimingMetric come from icanboogie/http, which gained support for the header: $response->headers->server_timing->add('db', 12.3, '7 queries').

Opt-in configuration

The feature is off by default. It's enabled with the application configuration, using the AppConfigBuilder:

<?php

// app/staging/config/app.php

namespace ICanBoogie;

return fn(AppConfigBuilder $config) => $config
    ->enable_server_timing();

The builder also has add_server_timing_provider() and remove_server_timing_provider(), to add your own provider or to drop one that a package registered.

Packages register their providers

Packages add their provider with an app config fragment. Installing bind-event is enough for the event metric to show up once the feature is enabled:

<?php

// bind-event/config/app.php

namespace ICanBoogie;

use ICanBoogie\Binding\Event\EventServerTimingProvider;

return fn(AppConfigBuilder $config) => $config
    ->add_server_timing_provider(EventServerTimingProvider::class);

I considered registering the providers when the application boots, but the application configuration is read-only and built before the boot, I would have needed a second, mutable registry. A fragment is declarative, it's part of the cached configuration, and it costs nothing per request. The fragment of the application is applied after those of the packages, so it can remove what they added.

Providers are services. They're resolved from the container by class name, so they must be public:

ICanBoogie\Binding\Event\EventServerTimingProvider:
  public: true

The explicit step

Application::run() gets one step between the moment the response is produced and the moment it's sent, because headers are final once the response is sent:

$response = $this->service_for_class(Responder::class)->respond($request);

if ($this->config->server_timing) {
    $this->alter_server_timing($response->headers->server_timing);
}

$response($request);

When the feature is disabled, nothing is resolved and the header isn't read. Otherwise, the application resolves all the providers first, then calls them in the order they were added. Resolving first keeps the cost of building the providers, which can build configurations or open connections, out of what the other providers measure.

I first wanted a listener on an event, but emitting an event disturbs what EventProfiler measures. The timing listener would be profiled while it reads the profiler, and without any listener the event would be recorded as emitted for nothing. The unused and calls figures would include the work done to produce them. An explicit step emits nothing.

What the providers report

Providers aggregate. One metric per kind of data keeps the header small, and avoids leaking details like class names or SQL statements.

Package Provider Metric
icanboogie AppServerTimingProvider app, from the start of the request until now
icanboogie ConfigServerTimingProvider config;desc="N configs"
bind-event EventServerTimingProvider event;desc="N used, N unused, N calls"
bind-activerecord ActiveRecordServerTimingProvider db;desc="N queries", sum of the established connections

For example, with the three packages:

Server-Timing: app;dur=334.42, config;dur=47.72;desc="6 configs", event;dur=4.2;desc="9 used, 12 unused, 31 calls", db;dur=12.3;desc="7 queries"

The db description is one I keep an eye on. A sudden jump there would mean something went wrong with my query strategy. It depends on the request, of course, but I want to keep that number low.

Nested work counts once

Records have a start time and a duration, and are added when the work ends. Work can nest: a listener emits an event, a configuration builder requests another configuration. Summing the durations counts nested work twice, and the total could exceed the time of the request.

For config and event, the duration is the length of the union of the intervals. The records are sorted by start time and overlapping intervals are merged, so an inner call that lasts 1 second inside an outer call that lasts 10 seconds counts for 10 seconds, not 11. Queries on one connection don't overlap, so for db the durations are just summed. The helper is a small class, Intervals::union_length(), that third-party providers can use too.

Units and precision

The measures come from microtime(true), the durations are in seconds with microseconds precision, and Server-Timing wants milliseconds. The providers multiply by 1000, they don't round, the rounding is done when the header is rendered. I only keep two decimals, that's plenty precision.

Writing your own provider

A provider is a class, a public service, and a line in the configuration:

<?php

namespace Acme;

use ICanBoogie\HTTP\Headers\ServerTiming;
use ICanBoogie\ServerTimingProvider;

final class CacheServerTimingProvider implements ServerTimingProvider
{
    public function alter(ServerTiming $timing): void
    {
        $timing->add('cache', 3.2, "12 hits");
    }
}

A provider that has nothing to report adds nothing, which is what happens with config when the configurations come from the cache and none was built. If a provider throws, the exception isn't caught, and the response isn't sent. It's meant for development and staging where a failure should be visible, and catching exceptions would require a log or an error metric that are easier to miss than the exception.

Limits

  • The header covers the work that precedes the response. Headers are sent before the body, so sending can't be measured, and what happens after the response is sent, in TerminateEvent, isn't included.
  • Error responses get the header only if the exception is turned into a response by the responder, which is what the WithRescue middleware does.
  • Long-running workers aren't supported. The profilers are static and never reset, and REQUEST_TIME_FLOAT is the start of the process, so the metrics would accumulate across requests. That's acceptable because those workers aren't meant to serve HTTP, and it could be improved by resetting the profilers after each response. Something for the future.

Seeing the metrics in Firefox

Open the developer tools, select the Network tab, and click a request. The metrics are listed in the Timings panel of the request, with their descriptions. It works for every request in the list, including the fetch() calls of the Vue application, which is where I needed it.

The panel shows one request at a time. To get an overview of a page load, the performance entries can be summed in the console. The document itself is a navigation entry, the other requests are resource entries:

const totals = {};

for (const entry of performance.getEntriesByType('navigation').concat(performance.getEntriesByType('resource'))) {
  for (const { name, duration } of entry.serverTiming) {
    totals[name] ??= { duration: 0, count: 0 };
    totals[name].duration += duration;
    totals[name].count++;
  }
}

console.table(totals);

Requests run in parallel, so the totals tell where the time goes, not how long the page took to load.

Summary

The telemetry already existed, Server-Timing provides a standard way to expose it. The bind-* packages adapt their telemetry to providers, the telemetry packages are unchanged, and when the feature is disabled the cost is one boolean check per request. API requests, which an HTML comment couldn't cover, now show where their time went.

The feature will be part of ICanBoogie v7.0.0. The ADR has the details, including the options I rejected.