Pomm: A two hours run with Blackfire.io

Editor’s note: This is a guest blog post by Grégoire Hubert. Here, he shares his first impressions profiling the Pomm Open-Source project using Blackfire.io.

I was at the SymfonyCon in Madrid last week when I saw the stand advertising for Blackfire, SensioLabs latest product. It was the perfect time to give it a go. So I sat down at the desk and accompanied by Hugo Hamon who did not have the time to test it before, I started the installation process.

As I am reluctant to install test software on my laptop, I chose to install debian packages in a LXC container. A couple of apt-get commands later, I installed the Chromium browser, got the Blackfire extension and was fully ready with a working bench. Make it to work in a LXC container did comfort me in thinking it would also work using Docker.

I must confess I had an idea in mind when I thought about testing Blackfire. We have been working on Pomm2 the last couple of months and although we had performance in mind when coding the packages, we could never actually really test what it was about. Pomm is a Database Access Layer dedicated to Postgresql coupled with a model manager. Needless to say performance is critical for us and some milliseconds saved could sum up to seconds when iterated thousands of times.

For the example’s sake, I did set up a simplistic table plop and inserted a million rows in it:

create table plop (pika text, chu int4);
insert into plop select cast(random() as text), generate_series(1, 1000000);
select * from plop limit 5;
       pika        | chu
-------------------+-----
 0.947555962949991 |   1
 0.675106787122786 |   2
 0.213856556918472 |   3
 0.53550627687946  |   4
 0.792278020177037 |   5

I then fired up Vim and once Composer invoked, started to code a simple test case that should be no problem:

// index.php

$pomm = require __DIR__.'/../.pomm_cli_bootstrap.php';

$results = $pomm['my_db']
    ->getModel('\MyDb\PublicSchema\PlopModel')
    ->findWhere('chu = $*', [500000]);
header('Content-Type: application/json');
print json_encode($results->extract());

The code deserves a couple of explanations to understand what is going on behind the scenes.$results is actually an iterator on the database results, the rows are lazily fetched on demand and every time hydrated into a Plop entity instance. The extract() method is an equivalent of a fetchAll method but entity instances are converted back to an array. This is a convenient method to send JSON responses back and still benefit from entity getters methods. In this very simple case, there should be only one result. A look in Chromium confirmed this:

A click on the now permanent Blackfire button on top right of Chromium started the inspection. 15 seconds later, I was able to browse the graph window and the results were interesting already:

• Total execution time: 320ms
• Total time spent in setting up the database connection: 58.7ms (18.3%)
• Total time spent waiting for the database result: 229ms (71.4%)

This is easily explained by the fact the table has no indexes. Postgres must perform a full table scan on the million rows before sending back the line we asked. The total IO time was 271ms and the total PHP execution real time was 49ms. The total RAM used in the operation was 745Kb. This seems huge compared to the tiny result we asked. One more time, examining the graph showed that 88.3% of the RAM used was eaten up by the autoloader (685Kb).

Great, let’s now take a more stressing approach:

select count(*) from plop where pika ~* '777';
 count
-------
 11764
(1 line)

This query was just to see how many rows are matching the given regular expression regardless the case. It says there are 11,764 rows containing 3 sevens in a row in the pika column. This is enough to perform some dumb brute testing. It is just a matter of replacing the condition in thefindWhere method: ->findWhere('pika ~* $*', ['777']) to be flooded with more than 11k JSON objects. Refreshing the page takes now a lot more time and since Blackfire launches the test ten times, it took about 2 minutes to get done with the profiling. The graph then looked dramatically different.

The total execution time to hydrate and output the 11,764 results was 11.6s with 7.32Mb RAM consumption. A zoom on the critical path showed 33% of the execution time was spent on data type conversion. Pomm actually converts data from database types to according PHP types. The JSON output presents the chu field as an integer and pika as a string. The hydration plan is called once per result and since each result has two fields, there are 23,528 calls to the converter system. The graph clearly showed the execution path to divide nicely its 33% into 3 sub execution trees, 3,84s is spent here which is actually pretty nice. It is also noticeable on the right that the call to pg_get_result takes 10.6% of the time (1.21s) so it seems to behave better with a lot of results. The surprise came from another part of the graph.

Even though the extract() method spent 53% of the time on fetching, converting and hydrating the data into entities instances, 30.7% of the time was also spent on extracting data from these entities to arrays. The analysis pointed out the method getIterator using an anonymous function. This piece of code was actually inspecting the instance methods to check if it had hasX method to check if yes or no it had to use overloads. This check was made for every instance using a couple of costly preg_match function calls.

It could clearly be an optimisation here. Since all the extracted instances are the same type, it could be possible to inspect the first instance and store the list of the hasX methods in a static attribute. This was a quick solution and Blackfire was launched again. Unsurprisingly, this branch did disappear from the result board. One of SensioLabs’ developer, amused by our interest in the tool, showed us how to compare two inspection result sets to outline their differences. I must admit this is a killer feature.

The graph clearly indicates the modification did lower the execution time by 3s (-35%) down to 8s. Exporting hundreds if not thousands results in JSON API is common. Because the execution time did seem good at first glance, the problem would have remained unseen without the two hours we spent playing with Blackfire. 35% performance improvement is a major enhancement in such a test case.

We want Pomm to be the fastest object model manager for Postgresql. Even though we know it is already, it is now clear we can shape it like a bullet. We will prepare a serious performance test bench before we release Pomm2 in the months to come. What happens if a table has more than 100 columns? Is converting HStore or Json the same? How logging queries impacts on performances? These are some of the questions Blackfire will answer.

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.