Mergebot Now 1,200% Faster: Tuning a Laravel App with Blackfire

We just hit a huge milestone in our Mergebot beta by lifting the 1,000 queries per deployment limit 🎉. We created Mergebot to make merging WordPress databases easy. When we were building Mergebot, the problems we were focused on solving were so complex that we didn’t really spend much time thinking about optimization or making our code run quickly. However, it became clear that we needed to do something about the performance of the app, especially the performance of our deployment generation jobs, to be able to lift the 1,000 queries per deployment limitation.

As part of my work on lifting the limit, I needed to ensure that deployments wouldn’t just fail because of timeouts or hitting memory limits. Enter, Laravel.

As you probably know by now, the Mergebot application is built using Laravel. We use Laravel’s Queue Jobs to handle any long-running processes (e.g. generating a deployment) so that the workload can be offloaded from the web server and scaled separately.

My first port of call when it comes to profiling PHP applications is Blackfire. Blackfire’s premium plans offer all sorts of fancy performance monitoring features, which are definitely worth checking out, but their free plan allows you to profile web pages, CLI scripts, and API Calls allowing you to measure wall time and memory usage. This is more than enough to get you going when you need to look for performance bottlenecks in PHP code.

In this article, we’re going to look at how to profile a Laravel application and specifically how I profile a queue job using Blackfire. We will have a look at how we should interpret the results and see how I managed to improve the performance of Mergebot by 1200%.

Laravel and Blackfire

The first thing we need to do is get Blackfire up and running on the server that is running our Laravel app. For the purposes of this tutorial, we’re going to use a Laravel Homestead VM, but these instructions would apply for any server that you run your Laravel app on.

If you haven’t done so already, head on over and sign up for a Blackfire account. Once logged in, navigate to the account page where you should see your client credentials. You will need this information shortly.

I’m going to assume you have your Laravel app already set up on Homestead (or your server). Homestead saves us a bit of time by coming with Blackfire pre-installed, but if you don’t have Blackfire installed yet then simply follow the instructions from the Blackfire docs (we need the agent, the CLI tool, and the PHP probe all to be installed).

We can test our Blackfire installation by profiling a built-in Artisan command. SSH to Homestead then run the following from the root of your app:

blackfire run php artisan route:list

If this is the first time you’ve run Blackfire you will probably see an error about “Blackfire isn’t configured correctly”. If this is the case then run blackfire config, following the instructions and using the information provided from the account page in the Blackfire dashboard. Once that is done, run the above command again. Hopefully, you should see something like this:

Output of blackfire run command

If we visit the Graph URL (or just head to the Blackfire Dashboard) you should see the results in the list of profiles.

Profiling Jobs using Commands

Next, we’re going to create an Artisan command to test our job class. If you already have a job class you want to test, feel free to use it. Otherwise, we can create a dummy job to use for testing purposes. To do this, run the following:

php artisan make:job DummyJob

You should now see a DummyJob class in the app/Jobs directory of your Laravel app. Normally to run this job you would need to set up a queue worker, dispatch the job and then wait till it was picked up and executed by the queue listener. However, this process isn’t going to help us much when it comes to profiling the code that is run while the job is being executed. Instead, I like to create an Artisan Command specifically for executing the job so we can run it using the CLI. Let’s go ahead and create the command:

php artisan make:command ExecuteDummyJob

This will create an ExecuteDummyJob class in the app/Console/Commands directory. There are two changes we need to make to this class. First, give the command a proper signature:

protected $signature = 'app:execute-dummy-job';

Second, we need to execute the handle method of our DummyJob class (this is what the queue worker would normally do):

use App\Jobs\DummyJob;

/**
 * Execute the console command.
 *
 * @return mixed
 */
public function handle()
{
    $job = new DummyJob();
    $job->handle();
}

Finally, remember to add our new command to the Kernel.php class so that we can run it:

/**
 * The Artisan commands provided by your application.
 *
 * @var array
 */
protected $commands = [
    \App\Console\Commands\ExecuteDummyJob::class,
];

Now if we run php artisan app:execute-dummy-job we are basically replicating what would be executed by the queue listener, except that now we can profile it using the Blackfire CLI:

blackfire run php artisan app:execute-dummy-job

Interpreting Blackfire Results

For this section, I’m actually going to look at a real world example from Mergebot, but if you’ve got your own job, or you’ve just set up the DummyJob and added some code to profile, you can use that as the basis for investigating your results. Here are the results from running a 60 query deployment on the old Mergebot code:

Mergebot call graph in Blackfire

The first thing I’d recommend doing before jumping into these results is to read Blackfire’s own docs on Analyzing Profiles. This should give you a decent understanding of how the Blackfire results page works.

Next, you should notice the main result metrics for this profile: it took 2 mins 10 secs to run using 22.1 MB of memory. These are going to be the main performance indicators that we are trying to reduce.

Mergebot metrics results in Blackfire

In the main call graph, we can see the flow of the code execution including how many times each method was called and where the “hot path” leads (where most of the execution time was spent). The Blackfire docs recommend always analyzing the hot path first to see if it is being caused by an obvious bottleneck, but be aware that sometimes the hot path is entirely justified and not actually an issue.

In this case, the two hot paths lead to fgets (reading from the cache) and PDOStatement::execute (executing database queries).

Blackfire hot path results

This doesn’t tell us much on its own. However, notice how often each of these methods is being called. Reading from the cache (fgets) is being called more than 58,000 times, and there are more than 8,500 database queries being executed, all for a 60 query deployment! No wonder we are having performance issues. Let’s head back up the call graph and see if we can identify where the issue is arising.

Performance bottlneck in call graph

Ah, now we can see where there is a clear performance bottleneck. The idRelatesToDifferentObject method was called 2790 times, mainly from the getFirstUpdateData and updateValueWithPlaceholder methods. This means that these methods are probably calling idRelatesToDifferentObject inside a loop that is happening way more often than anticipated. We’ve just found the location of a performance bottleneck that we can start refactoring.

This same process can be repeated as often as you need until you are happy with the performance of your code. Blackfire has another neat feature that lets you compare profiles to see the performance improvement. Let’s compare this profile to the new, re-written, deployment process code that I wrote for Mergebot.

Mergebot comparison call graph in Blackfire

The first thing to notice is the performance improvement of the main time and memory metrics:

Mergebot improved metrics results in Blackfire

Great Scott! This code runs in 8% of the time (that’s 1200% quicker than before) and uses less than half the memory. The same 60 query deployment now takes just 10 seconds. Not bad. Let’s look at the hot path for the new code.

Blackfire hot path results

The hot path still leads to the same types of event (reading from the cache and executing database queries). However, notice that we’re calling these methods much less than before. PDOStatement::execute went from being called 8700 times to 674 times. Limiting database queries is an effective way to improve performance.

If we head back up the call graph let’s see what happened to our method calls.

Blackfire method calls

The idRelatesToDifferentObject method has gone from being called 2790 times to 940 times. This is a decent improvement in itself, but it also has a knock-on effect on the number of times any methods are being called within the idRelatesToDifferentObject method. If we look at this in the comparison graph we can see the effect this has on the time of the execution.

Mergebot call graph time comparison

Improving Your App’s Performance

Hopefully, by this point, you’ve managed to get Blackfire set up on your Laravel install and are able to create profiles to benchmark your code. The process we used for creating an Artisan command to test queue jobs on the CLI can, in theory, be used to test any part of your code that you may want to profile.

In the Mergebot example, the main cause of the performance bottleneck was because we were calling code within loops a lot more than anticipated. This actually caused an exponential performance issue that made large deployments break completely. The simple solution to this type of performance issue is to refactor your code to call the methods less often. However, there are many different types of issues that may cause your code to run slowly and each project will face its own unique performance challenges.

What’s next for Mergebot? In the coming weeks, we’re hoping to launch another often requested feature: multisite support.

Have you ever used Blackfire to profile your code before? Do you have any tips on optimizing Laravel/PHP code? What performance issues have you run into in the past? Let us know in the comments.

If you want to have first dibs on the next round of seats for Mergebot, make sure you sign up here.

About the Author

Gilbert Pellegrom

Gilbert loves to build software. From jQuery scripts to WordPress plugins to full blown SaaS apps, Gilbert has been creating elegant software his whole career. Probably most famous for creating the Nivo Slider.

  • Renato Alves

    Really interesting tool, both mergebot and Blackfire.

  • I love Blackfire! I’ve used it fore the past few projects! Let me know if you want any suggestions on packages that make development /w laravel a little easier and nicer.

  • RonnieVisser

    Great article to get started with this!! Exactly what I needed.

    Does the execute job has any other reason to existence? Couldn’t you just set the QUEUE_DRIVER to sync?

    • Thanks Ronnie. As I explained in the blog post, the execute job is only really for convenience so we can easily execute portions of code from the command line. You could indeed set the QUEUE_DRIVER to sync, but you would still need a way to dispatch the job from the command line.

  • Shahroze Nawaz

    Any Future plans to write on blackfire with Symfony?

    • I’m afraid I don’t really work with Symfony, only the parts that are used in Laravel. The principles in this blog post could easily apply to a Symfony project too.

  • chrismccoy

    how can we get in on mergebot? applied months ago, how often are the invites going out?

  • Connor Brown

    Hi Gilbert,

    Great article! – What are you using to ssh into Homestead? I like the flat ui, looks great 🙂