Profiling Slow Requests

An endpoint answers in 900 ms. EXPLAIN from Indexing and Query Tuning says each query is fast, OPcache is on, and staring at the code has produced three theories and zero evidence. A profiler replaces theories with a per-function ledger: every function called, how many times, and the time spent inside it. You need one slow request captured, not a permanent slowdown.

Xdebug 3 folds everything into xdebug.mode (a comma list of develop, debug, profile, coverage). For profiling:

xdebug.mode = profile
xdebug.output_dir = /var/tmp/profiles
xdebug.profiler_output_name = cachegrind.%p
xdebug.trigger_mode = 1

Three details matter more than the mode itself. %p is the process ID — without it, two concurrent requests overwrite each other's profile and you analyze half of each. trigger_mode = 1 means the profiler stays dormant until a request carries XDEBUG_TRIGGER=1 (query string or cookie), so you profile five requests to /api/orders instead of every visitor's request. And the reason for that restraint is overhead: Xdebug's own numbers put the interactive debugger at roughly 3x to 20x slowdown, with the profiler lighter but still around 2x — double the CPU and a large file written per request. Profile mode on in production, untriggered, means gigabytes of /var/tmp and doubled load. Keep it triggered, keep it off until you need it.

Where the trigger comes from matters less than people expect: the query-string form works from curl, a browser, or a load generator, so you can profile one request or the first request of a wrk run and stop immediately. Xdebug 3.10 made XDEBUG_TRIGGER a first-class feature (query string, POST field, or cookie) precisely because the previous always-on modes had already caused production incidents at more than one company. One operational trap remains: FPM workers read their mode at startup, so after editing xdebug.mode you must systemctl reload php8.3-fpm — an ini change never reaches already-running workers, and you will otherwise profile zero requests and wrongly conclude the trigger is broken. That is the same process-restart rule you met for OPcache settings, applied to a different directive.

Capture the request:

curl -s -o /dev/null 'https://app.example.com/api/orders?XDEBUG_TRIGGER=1'
ls -lh /var/tmp/profiles/

Then open the cachegrind file. GUI viewers (QCachegrind, KCachegrind, PhpStorm's built-in) render it as call trees and graphs; callgrind_annotate works from a shell. The format itself is plain text: one line per function with two cost columns, and the skill is knowing which to trust. Self time is time spent in the function's own statements; inclusive (cumulative) time adds everything it called. A front controller or middleware entry point shows enormous inclusive time and trivial self time — it is a doorway, not the culprit. The expensive work hides one level down: a helper with 600 ms self time, or — the pattern you learn to recognize instantly — PDOStatement::execute appearing 612 times with 1.4 ms each. Hundreds of identical small entries are an N+1 signature no aggregate view shows you.

Rank by inclusive time first to find the region, then by self time inside it to find the statement. That sequence — region, then statement — is the whole method, and it is what you narrate in an interview: not "I added an index," but "the profile showed 612 executions of PDOStatement::execute totaling 690 ms, which was an N+1, so I added an eager load." Chapter 2 covers a profiler built for a different constraint: sampling production-like traffic without paying Xdebug's bill.

Xdebug's profiler is a light switch: the whole process is on or off. Blackfire splits the cost in two with a client/server architecture — a small C extension (the probe) is always installed, and the expensive part, recording a profile, happens only for requests that explicitly ask. That separation is why Blackfire can live on production traffic and Xdebug generally cannot.

The pieces: the probe extension in PHP, a host agent, and the CLI talking to Blackfire's server. Then any request becomes profileable by wrapping it:

blackfire curl https://app.example.com/api/orders   # profile one HTTP request
blackfire run php artisan report:generate            # profile a CLI command

The CLI sends the trigger (X-Blackfire header) and downloads the result, so nothing about your code changes. Overhead numbers are the selling point and the reason to choose this tool deliberately: an untriggered probe costs on the order of 0–2% — that is Blackfire's published figure and the design target — while a recorded profile adds cost to that one request only, in the tens-of-percent range rather than multiples. Compare that to Xdebug's roughly 2x while profiling and the choice matrix is simple: local deep dives on one endpoint — free Xdebug, no infrastructure; recurring measurement or anything resembling production — Blackfire (or the XHProf lineage: Tideways, XHProf itself, whose overhead philosophy is the same).

What you gain beyond low overhead is the shape of the output. Blackfire splits wall-clock time from CPU time, which changes how you read an expensive call: an HTTP client showing 400 ms wall and 2 ms CPU is waiting on a payment API — no amount of PHP optimization touches that number, but a timeout or an async queue does. It breaks a request into dimensions — CPU, memory, I/O, SQL, network — per function, so "the request is slow" becomes "SQL is 68% and two statements are 80% of that."

The feature that justifies the setup is the profile diff. You optimize, profile the same request again, and Blackfire compares the two profiles call path by call path: what got cheaper, what got slower, what the totals are now. Before/after stops being an anecdote and becomes a table you can paste into the pull request — exactly the artifact the "measure before and after" discipline in Chapter 3 demands, produced by the tool instead of assembled by hand. In practice the diff reads as a table of call paths with before, after, and delta columns: the eager-load fix moves SQL time from 690 ms to 14 ms while adding 2 ms of hydration — a 676 ms win you can defend line by line instead of asserting. Stored profiles also make performance reviewable: a colleague opens the same request's profile from a link in the pull request without reproducing anything on their machine, and the argument happens over the same data. Teams that take this furthest attach cost budgets — fail the build when a route's profiled cost exceeds its agreed number — which converts performance from a quarterly emergency into a merge-time check.

One habit carries across both tools: profile against realistic data. A 12-row development database hides the query cost, the sort, and the serialization size that dominate production — a profile of an empty app measures your framework's boot, not your workload. Seed hundreds of thousands of rows, or profile staging, before trusting any ranking the profiler gives you.

A profile found the hotspots. You fixed them. Now the only question left is whether the endpoint is actually faster — and the failure mode here is not technical, it is methodological. Four rules keep the answer honest.

Warm up first. The first request after a deploy compiles OPcache, connects to MySQL, and fills the buffer pool; it is not comparable to anything. Discard the first several requests, then measure steady state. Sample, don't cherry-pick. Thirty-plus runs, report the median and p95 — never the single best time. One change per measurement. If two fixes landed together, neither gets credit. Same environment on both sides. A "before" run with Xdebug's profiler active versus an "after" run without it measures Xdebug, not your fix — this is the single most common way a fake improvement reaches a slide deck.

The load generator is part of the method:

wrk -t4 -c50 -d30s http://localhost:8080/api/orders

Medians from wrk (or ab, hey) before and after each change, plus a fresh profile to confirm why the number moved, is the full loop. Watch the latency distribution, not just the mean: an N+1 fix often leaves the mean nearly flat while p95 collapses, because the pathology punished large pages and slow queries disproportionately.

A worked example of the loop in full. The profile of a 1.1 s request ranks: 700 ms inclusive in a helper that unserialize()s a session blob per request; 690 ms across 612 PDOStatement::execute calls (the N+1); 180 ms in json_encode over 4,000 rows. Fixes, each measured alone: slim the session to the three keys the route reads (cache-aside per key), Order::with('customer'), and select six DTO columns instead of *. Re-profile and re-run wrk: 1.1 s → 210 ms median, with the profile showing the same request shape and none of the three hotspots. Both halves of the evidence — number and cause — travel to the interview.

Flame graphs compress the reading step: x-axis width is inclusive time, color marks self time in most renderers, and one glance at a wide stack of hundreds of PDOStatement::execute slivers says "N+1" faster than any table. QCachegrind and Blackfire both export to flame-graph tooling.

Statistical hygiene deserves its own line. With 30-plus samples, compare medians and the spread between runs — if the before and after distributions overlap heavily, the change has not been proven, and the honest report is "no measurable difference yet" rather than a headline number. Server-side percentiles come from the same sample: sort the latencies and read the 95th value directly. Keep the raw table in the pull request; six months later, when someone asks why with('customer') appears everywhere in the codebase, that table is the answer.

Know the standard false positives so you reject them on sight: micro-benchmarks that loop one function a million times (array caching and JIT behavior distort results); comparing runs where one side had xdebug.mode = debug (the debugger alone is 3x–20x); second-run timings that quietly hit the application cache you added — which is a real win but must be labeled "warm" rather than compared against a cold baseline; and single-run comparisons across network jitter.

Interviewers remember numbers. "I profiled a 900 ms endpoint, found 612 queries from an N+1 plus a per-request unserialize, fixed both, and verified 950 ms → 120 ms at p95 with wrk" is a different answer than "I optimized the database." The measurement story is what ships next — Deploying behind Nginx and PHP-FPM.