Profiling and speeding up a PHP app with Blackfire.io
Profilování a zrychlování aplikace s Blackfire.io. A two-hour live stream with no slides. I took a REST endpoint from Entrydo that took about ten seconds to answer, profiled it with Blackfire, and went looking for the slow parts on air, mistakes included.
What Blackfire is
Blackfire is a profiler for PHP. It measures how much time, CPU and memory a request takes, which functions it calls, how many times, and how long each one takes. With a paid plan it also shows the SQL queries and their timing. You can also use it for performance testing in CI: you write assertions such as “this request must not take longer than X”, and the build fails when one is broken.
It has three parts on your machine:
- The probe: a PHP extension that collects the data.
- The agent: a small daemon that sends the profiles to blackfire.io, where you look at them. It is linked to your account with API credentials.
- The CLI tool (
blackfire) and a Chrome extension, called Blackfire Companion, to start a profile.
On a Mac it’s a few Homebrew commands: install the agent, register it with your credentials, and install the probe for your PHP version.
The big difference from Xdebug: an installed Xdebug slows down every request, while Blackfire slows down only the requests you are profiling. That’s why Blackfire says you can run it in production.
In March 2018 the free plan profiled pages and CLI scripts, but it didn’t show SQL queries, and I remembered it not profiling HTTP API requests either, which rules it out for a REST API. We paid for the cheapest plan, about $20 a month but billed only yearly. Assertions and CI builds were in the Premium plan at about €82 a month, and integrations like GitLab and Slack only in Enterprise. (2:44)
Reading a profile
Each profile shows the URL, the method, the PHP version, the response size and the totals: wall time, I/O wait, CPU time, memory, network, HTTP calls and SQL queries. Click a dimension and the whole graph switches to it, so when you hunt a memory leak you switch to memory. A timeline shows what ran when. (8:22)
One warning from experience: the times in Blackfire don’t match production. In my case they were about 50% higher: a request that took 12 seconds on the server showed 18 seconds in the profile. Use the numbers to compare, not as absolute truth.
The left side is a table of functions with call counts and two times:
- Exclusive: time spent in the function itself.
- Inclusive: time including everything the function calls.
Sorted by exclusive time, you see where the time actually goes. In the call graph, the lighter colour is the inclusive part and the stronger colour the exclusive part, and each function shows its callers and the functions it calls.
Blackfire also gives recommendations. Ours said that Doctrine metadata should be cached in production (our XML mapping through Kdyby/Doctrine couldn’t be cached yet) and that 679 SQL queries per request is a lot. I agree.
Profiling a page and an API call
For a web page, open it, click the Blackfire icon next to the address bar and press Profile. You can also turn on profiling for every page you load. Blackfire first sends one warm-up request to fill caches, then several more (10 by default) and averages them, so a short hiccup on your machine doesn’t skew the result. (23:12)
The profile also warned me that Xdebug was on, which hurts performance. I left it on because I needed it later.
For a REST API or a POST request, put blackfire in front of curl: (32:53)
blackfire --samples 5 curl -X POST -H "…" -d '…' http://localhost/api/…For a CLI command there is blackfire run. You can mark a profile as a reference, for example the version you deployed, and compare every later profile against it. Our plan allowed only two references.
The slow endpoint
Entrydo is ticketing software. Our worst endpoints were the lists of tickets and orders. Single-action presenters (Nette’s controllers) call a use case, which returns a response that turns entities into an array for the JSON output. The codebase is full of value objects, many of them pointless wrappers around a string, written before PHP 7 gave us scalar type hints. (35:41)
The endpoint listed the guests’ tickets of one event: about 4,000 tickets, 10 seconds in Postman and a 2 MB response. That is painful, and on mobile data it’s worse. Blackfire showed about 18 seconds. My goal was to get it under half. (42:01)
The function list already hinted where the problem was: hydrateColumnInfo was called 152,000 times, plus a lot of ObjectHydrator and reflection setValue calls. convertToPHPValue ran almost 33,000 times just for our entity ID type, and more for our date and string types. That is Doctrine ORM turning rows into objects.
Then I followed the call graph down, always to the most expensive child. The presenter itself took nanoseconds, but everything under it took 18.3 seconds. ListTicketsUseCase::handle() took 14.7 seconds, the repository method ofEvent() 14.5 seconds, and the exclusive time sat in Doctrine’s AbstractQuery::getResult(). Everything above that was fine and could be ignored. (48:01)
An Xdebug breakpoint after the query showed why: 4,109 ticket entities, each with value objects, fully loaded related entities and collections of more entities, mostly for nothing. (56:00)
Why not just select less? Because our entities contain logic: to answer “can this user edit this ticket”, the entity needs the user loaded too. When I started with Domain-Driven Design, I loved putting all logic into entities. This is the price. I would move such checks into a separate service.
Fix one: drop a value object
I had three ideas: remove pointless value objects, select only the fields we need (or skip the ORM entirely), and switch from XML mapping to annotations so the metadata can be cached. I started with the TicketCode value object, which had no reason to exist.
It had 86 usages, so I tried Rector by Tomáš Votruba, which had a rule to replace a value object with a simple type. On the stream it ended with an error, so I did it by hand. (70:55)
One tip from that refactoring. I kept the custom Doctrine type for the column for now and only generated a migration that drops the custom-type comment from the column. I learned this the hard way: once I deleted the type and added the migration in the same commit, and Doctrine crashed because the column pointed to a type that no longer existed. Do it in two deploys: the mapping change with the migration first, then delete the value object and the type. (92:12)
PHPStan and the tests caught what I missed.
The result: about 16,000 fewer calls and less memory. The times went up, but that was OBS, which I streamed with, keeping the CPU at 130–180%: one profile without any code change came out 7 seconds slower. Keep the machine in the same state between profiles, and on a busy machine compare call counts, not times.
Profiling from code
With the PHP SDK you can start a profile from code, for example in CI. I put it into bootstrap.php right after the autoloader, before the DI container is built, and ran it only when a request has a trigger header. Without that check, anyone could make your server profile every request, which is an easy way to DDoS you. Everything between creating the probe and ending it is profiled. (110:00)
if (isset($_SERVER['HTTP_BLACKFIRETRIGGER'])) {
$blackfire = new \Blackfire\Client();
$probe = $blackfire->createProbe();
register_shutdown_function(function () use ($blackfire, $probe) {
$blackfire->endProbe($probe);
});
}The SDK can go into normal dependencies, not dev ones, since Blackfire doesn’t slow down requests you don’t profile. The docs also had a Guzzle middleware for profiling calls to your microservices, and assertions in a YAML file, for example that every request under a path must take less than 100 ms.
Fix two: select only what you need
At the end I tried the second idea. I listed the fields the response actually uses and loaded only those with a Doctrine partial select: (125:09)
->select('partial t.{id, code, locale, email, firstName, lastName, …}')It took a few attempts (status was a method, not a property, and I forgot locale), but in the diff it was one changed line. The request was clearly faster even by eye. Blackfire showed about 50,000 and another 47,000 fewer calls, far fewer convertToPHPValue calls, and 1.9 seconds less in hydration. Looking back, I should have started with this one-line change instead of the value object.
The next steps would be the same for the second entity, and then going around the ORM: write plain SQL with Doctrine DBAL, get the rows as arrays, and if you don’t want to work with associative arrays, wrap them in a small read-only DTO.
Alternatives
A viewer asked for a free alternative. Xdebug has a profiler, and Webgrind is a web interface for its output. It works, but it’s not as nice as Blackfire. Another viewer uses XHProf, which has call graphs, call counts and times too. (135:43)
My advice: profile before you optimise, so you have something to compare against. Then make one change at a time, measure, and revert anything that doesn’t help.