A Quick Profile of PhpSpec using Blackfire.io

Editor’s note: This is a guest blog post by Ciaran McNulty, trainer for SensioLabs UK. Here, he shares his first experience profiling the PhpSpec Open-Source project with Blackfire.io.

Although I work as a trainer for SensioLabs UK, I was in the same boat as the rest of the audience at SymfonyCon this Friday when Blackfire.io was announced, as I had seen nothing yet of the ‘SensioLabsProfiler’.

Like a lot of PHP devs, I had experimented with Xdebug and Xhprof in the past but had always faced a struggle when trying to install and configure them followed by a struggle to read the output. From the brief demo I saw, Blackfire looked like it was a good product for me: something that would hold my hand through the process.

As a contributor to PhpSpec (A SpecBDD or Unit Testing tool) I was interested to see how Blackfire would work with CLI applications, so once back in London I decided to give it a try. Before going any further I should say that PhpSpec has not particularly been tuned for performance and I was not expecting any big wins, but I was interested to see how the tool behaved.

Registration and Installation

Signing up to the service was simple as I already had a SensioLabsConnect account. If you don’t it’s a fairly straightforward registration form before you are dropped straight into the Blackfire control panel.

Reading the Getting Started instructions, there were 3 components I needed to install:

• The “Companion”, a browser extension for running profiles against websites, I did not need this for testing on the CLI but installed it anyway
• The “Probe”, a PHP extension that gathers profiling data.
• The “Agent”, a service that runs on the same machine, gathers Probe data and aggregates/batches it out to Blackfire

Installing the Companion was a familiar process from using other Chrome extensions. To install the Probe and Agent I was pleased to see thought had been put in to providing OS X instructions and Homebrew packages, so everything was installed in a few brew commands. Installation on various Linux distributions seemed similarly straightforward.

Setup took maybe 10 minutes in total, mostly waiting for brew to do its stuff.

Profiling PhpSpec

Blackfire offers 20 slots in which you can store data, so the first thing to do is decide which one the profiling data is going to go into. A few clicks in the web interface generate a ‘signature’ which you then set before running your PHP application. I used this to execute PhpSpec’s own test suite on the master branch
BLACKFIRE_QUERY="<signature code>" bin/phpspec run
Nothing looked different on the CLI (and as an aside, the time to run was pretty much the same as before installing the PHP extension), but when I returned to the Blackfire web interface my first slot was populated with data. Clicking through showed a quite readable execution graph.

This clearly isn’t the whole execution graph of the code, it’s subject to some fairly customisable thresholding and filtering, but the presets gave me a pretty good idea of what was going on inside PhpSpec. One area in particular got me interested immediately:

This describes what happens when PhpSpec executes a particular example (An Example is like a test case). The majority of its time is spent inside Reflection::invokeArgs, which makes sense because this is how we run each Example and we’d expect PhpSpec to spend most of its time executing Examples. Blackfire has filtered out everything beneath this because there aren’t many common operations inside Examples.

However, on the left we can see a particularly time-consuming branch that seems to be repeatedly sorting doing a usort – more than 6,000 times in fact! This is an area that can certainly bear more investigation.

To give some context, in PhpSpec a Matcher is similar to an Assertion in some other testing frameworks. An Example might look like:

function it_says_hello_world()
{
    $this->greet()->shouldReturn('Hello World');
}

Here shouldReturn is referencing a Matcher object. PhpSpec has a set of default Matchers, then extensions can register Matchers, then finally users can define their own Matchers inline inside specs.

This complexity is handled by two objects: MatcherMaintainer and MatcherManager but they do not seem to do this efficiently. Because each Example can have different inline Matchers, the list of Matchers cleared and then all the Default matchers re-added, before every example is run.

Unfortunately, the add method looks like this:

/**
 * @param MatcherInterface $matcher
 */
public function add(MatcherInterface $matcher)
{
    $this->matchers[] = $matcher;
    usort($this->matchers, function ($matcher1, $matcher2) {
        return $matcher2->getPriority() - $matcher1->getPriority();
    });
}

This means before every spec, 10-15 objects are sorted based on the result of a method call. Finding this bottleneck took at most around 10-15 mins after the installing all of the Blackfire components. The next thing to do was fix it.

Optimising

The fix was fairly simple – adding a way to set the default matchers without triggering re-sorting, and only bothering to sort when a custom inline matcher is involved. Implementing and testing this took slightly longer (partly because of a dead end approach I quickly abandoned).

Once the test suite was back in a passing state after my changes I thought I’d probably improved the situation, but the only way to tell was to re-run the profiling, this time specifying a different profile slot. The difference was immediately obvious:

The code branch I’d been trying to improve has now disappeared because it has fallen below Blackfire’s default filtering, and the execution path is much more what I’d expect. The CollaboratorsMaintainer path has become more prominent because of this, and it’s obvious that there may be some improvements possible in that area as well.

But aside from the pretty picture, is it faster?

Comparing multiple profiles

Blackfire has a nice mode that shows the difference between two profiles and highlights which areas are faster and which are slower. In my case every area sped up, and I got this nice result at the top of the screen:

To put this into perspective, the whole suite executed in 11.2s beforehand so this is around 10-15% faster than before – pretty significant.

In conclusion

From never having used Blackfire, to having improved the performance of an open-source tool I like by 10% (if the PR is accepted of course) took much less than an hour. On that basis, I am pretty blown away by Blackfire.

The main advantages for me over other solutions were the clarity of the reports, and the ease of setup. From what I’ve seen so far of the browser-based profiling the same applies there.

Fundamentally as a PHP profiler Blackfire isn’t going to give you any data you could not get from Xhprof if you know what you are doing, but for people like me who develop first and profile when there’s an issue it sets a very low barrier to entry in the world of performance profiling.

I’ll certainly be using it again in future!

Editor’s note: We are always looking for great stories about how Blackfire helped our users find bottlenecks and improve the performance of their apps. Feel free to contact us if you are interested in sharing your experience with Blackfire.