Measuring Properly

Timing a block with hrtime, using a profiler instead of guessing, load testing an endpoint, and keeping a number you can compare.

Syntaxhrtime(bool $as_number = false): array|int|float|false

"It feels slow" is not a measurement, and the part of the code everyone blames is usually not the part that costs the time. Three tools answer three different questions, and confusing them wastes days.

Timing a block

hrtime(true), added in PHP 7.3, returns nanoseconds from a monotonic clock, one that cannot jump backwards when the system clock is adjusted. microtime(true) can. Run the block once without timing it to warm it up, then time it several times and take the median. A single run includes first-call compilation and fresh allocations; a mean is dragged around by one unlucky run.

Finding the cost

Timing tells you a block is slow, not why. A profiler records the calls and shows where the time went. Xdebug's profiler writes a cachegrind file you open in a viewer; sampling profilers cost far less and can be left running in production. Pick the target with a profiler, then confirm the fix with your own timing.

Load testing

One request on an idle machine says nothing about 200 at once, where connection limits, worker counts and locks start to matter. A load generator sends a set number of requests at a set concurrency and reports the distribution. Quote p95, the time under which 95 percent of requests completed, rather than the average, because the average hides the slow tail users actually notice.

A number you can compare

Record the same measurements on the same data every release: p95 for a few key endpoints, queries per page, peak memory. One number from one release means nothing. The series is what tells you a change made things worse.

Example

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

When to use it

  • Finding which of four stages on a slow page actually owns the time, before changing any of it.
  • Confirming that a rewrite made an endpoint faster rather than assuming it did.
  • Checking how an endpoint behaves at 20 concurrent requests instead of one.
  • Keeping a p95 figure per release so a performance regression is caught in the next deploy.

More examples

Timing a real block and logging it

Reach for this when you have a slow page and want to know which stage owns the time, without installing anything. The finally block runs even when the callable throws, so a failing request still logs how long it took before failing. Labels are hierarchical on purpose: grep the log for products. and the breakdown is there. Dividing by 1_000_000 converts nanoseconds to milliseconds, and the underscores in the literal are a readability feature, not a different number.

Example · php
<?php

declare(strict_types=1);

/**
 * @template T
 * @param callable(): T $block
 * @return T
 */
function timed(string $label, callable $block): mixed
{
    $start = hrtime(true);

    try
    {
        return $block();
    }
    finally
    {
        $ms = (hrtime(true) - $start) / 1_000_000;
        error_log(sprintf('%s took %.2f ms', $label, $ms));
    }
}

$rows = timed('products.listing', static fn (): array => $repository->listing(1, 50));
$html = timed('products.render', static fn (): string => $view->render('products', $rows));

A profiling run with Xdebug

start_with_request=trigger is the setting that makes this usable: without it every request is profiled and the output directory fills in minutes. With it, nothing is profiled until a request carries XDEBUG_TRIGGER, so you profile exactly the page you care about. Read the result as proportions, never as timings, because the instrumentation itself dominates the absolute numbers. What it answers well is which function was called 4,000 times when you expected 40.

Example · ini
; dev or a staging box only - the profiler makes everything several times slower
xdebug.mode=profile
xdebug.start_with_request=trigger
xdebug.output_dir=/tmp/profiles

; Then request the page once with the trigger, for example:
;   curl -s 'http://localhost:8080/products?XDEBUG_TRIGGER=1' > /dev/null
;
; and open the cachegrind.out.* file written to /tmp/profiles in a viewer
; such as KCachegrind, QCacheGrind or an IDE that reads the format.

Load testing an endpoint

Run this against a build with Xdebug off and OPcache on, or you are measuring the development environment rather than the product. The percentile table is the output worth keeping: the 50 percent figure describes a typical request, the 95 and 99 percent figures describe the ones that generate complaints. Keep the request count, concurrency, machine and dataset identical between runs, because changing any of them changes the number more than most code changes do. wrk and k6 do the same job with better concurrency handling when ab becomes the bottleneck.

Example · bash
# 500 requests, 20 at a time, against a warmed-up page
ab -n 500 -c 20 'http://localhost:8080/products' | sed -n '/Percentage/,$p'

# the lines that matter
#   Percentage of the requests served within a certain time (ms)
#     50%     94
#     95%    182
#     99%    410

# record it per release so the series can be compared
echo "$(git rev-parse --short HEAD) products p95=182ms" >> perf-log.txt

Related

php n plus onephp memoryphp cachingphp health monitoringhrtime

Discussion

  • Be the first to comment on this lesson.