Chapter 4 - Your First Profile¶

Step 1: Gathering Data¶

The first step in our quest is to gather data about the behavior of the current codebase by using the Blackfire profiler. To do that, we will generate profiles for GitList’s home page (/) and each of the tabs on the repository page: “Files” (/Twig), “Commits” /Twig/commits, “Stats” (/Twig/stats), and “Network” (/Twig/network).

Before we do this, you will need to create an account on Blackfire.io if you don’t have one yet. It takes less than a minute if you already have a GitHub, Google or Platform.sh account.

Then, make sure to subscribe to the Premium or Enterprise Edition. Premium does enable to profile non-local HTTP applications, and also offers more profiling dimensions (such as SQL) and a lot more features you’ll want to use in this tutorial, like assertions.

To trigger some GitList profiles, first install the Blackfire browser extension: for Firefox or for Google Chrome.

We are now ready to start our first profiling session!

To profile the GitList homepage, go to https://gitlist.demo.blackfire.io/ and trigger a profile by clicking on the Blackfire Extension icon:

By clicking the profile button, you have asked Blackfire to begin profiling the page currently displayed in the browser. You should see a black toolbar at the top of the browser window with a nice progress bar:

As you can see, it takes way more time to profile the page than it took to display it initially. This is because Blackfire triggers several page reloads behind the scenes to get a larger sample size, aggregate the results, and present more accurate information. Relying on only a single profile is not ideal, as we discussed in the previous chapter.

At the end of the profiling process, the toolbar displays a summary of the profile:

This summary provides some basic information (your numbers may vary slightly, but should be similar), from left to right:

• 26.7 ms: the time it took for PHP to generate the GitList homepage;
• 4.69 ms: the I/O time;
• 22 ms: the CPU time;
• 1.15 MB: the amount of memory consumed by PHP.

For now, we are only going to focus on main time and memory. We will discuss I/O and CPU in later chapters.

Hooray! You’ve just generated your first profile.

It took almost 27 ms for the server to generate the HTTP response. Is this good? Can we do better? When analyzing the performance of a project for the very first time, the slowest requests are the ones to optimize first. Now that we have our first profile, the baseline, let’s profile another page and see if its performance is different from the homepage.

Let’s profile the Twig project homepage, https://gitlist.demo.blackfire.io/Twig/. Load this page in your browser and use the browser extension to trigger a profile.

These numbers are quite different compared to the homepage. This page took more than 100ms to render (vs 14ms), and consumed around 2MB of memory (vs 1.5MB). It looks like this page can be optimized!

Step 2: Analyzing Profiles¶

The Blackfire summary toolbar is a good way to find which pages need to be optimized first, but then we need to dive deeper to better understand what’s going on. Click on the “View Call Graph” button now. You should be redirected to the detailed profile on Blackfire.io.

Your profile should be similar to this one:

Now it’s time to learn how to use the Blackfire interface to detect performance issues.

The table on the left side of the screen displays a list of the main functions and methods that were executed. Clicking on a function name reveals the resources consumed by this function, like time, memory, network, …

By default, the most time-consuming function calls are listed first. These functions are almost always where you want to look first. In our case, stream_select() comes first. It takes a significant amount of time to execute: almost half of the total time for 80 calls. As stream_select() is a PHP built-in function, it cannot be optimized; but we can try to lower the number of times it is called.

The next step is to understand which parts of userland code trigger these calls. Click on the stream_select() link to reveal this function’s details, then click on the magnifying glass. The call graph will now be redrawn and centered on this specific node:

The call graph displays the executed code as a visual diagram where each node corresponds to a function or method call. The edges of the graph show the execution flow.

Now that we are focused on the stream_select() node, drag the graph up with your mouse until you find the Gitter\Client::getVersion() and Gitter\Client::run() nodes. These are the first calls defined in userland PHP and the ones which we are most interested in:

Step 3: Optimizing the Code¶

The Gitter\Client::getVersion() method is called 10 times and accounts for 33% of the total execution time, that’s a lot. Its implementation reads as follows:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12

public function getVersion()
{
    $process = new Process($this->getPath() . ' --version');
    $process->run();

    if (!$process->isSuccessful()) {
        throw new \RuntimeException($process->getErrorOutput());
    }

    $version = substr($process->getOutput(), 12);
    return trim($version);
}

Apparently, getVersion() returns the version of the local git CLI tool, as getPath() returns the path to the git binary. We can safely assume that this method will always return the same result for any given request (and most of the time even across requests).

Caching the returned value locally avoids running 10 identical sub-processes:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18

public function getVersion()
{
    static $version;

    if (null !== $version) {
        return trim($version);
    }

    $process = new Process($this->getPath() . ' --version');
    $process->run();

    if (!$process->isSuccessful()) {
        throw new \RuntimeException($process->getErrorOutput());
    }

    $version = substr($process->getOutput(), 12);
    return trim($version);
}

And that’s it. In less than 5 minutes, in a codebase we knew nothing about before, we’ve already found a performance bottleneck and written a patch.

Blackfire provided us the tools necessary to understand the code’s actual behavior and showed us front and center exactly where to look to improve its performance.

We call that the “Blackfire effect”, and lots of people are experiencing it on their projects:

Woot! Thanks to @blackfireio, @michaelthieulin and I optimized one of the backoffice pages of @dayuse_fr. The page was taking 18 seconds to load due to a misconfiguration of our @MongoDB indexes on a 15M documents collection. Now, the pages loads within 200 ms. pic.twitter.com/KmX4yYxTd6

— Hugo Hamon (@hhamon) July 3, 2018

Used @blackfireio seriously for the first time yesterday. Went from 1min 39s to 2.98s on some heavy data processing code... It transformed our workflow in amazing ways. Thanks!

— belisar (@belisar) March 24, 2018

I think I found a way to improve performance by 15% in @phpunit using @blackfireio. Our unit tests take 17 seconds normally and with the changes it shaves off a few seconds. When running a code coverage report with xdebug on it shaves off several minutes. I will submit a PR soon.

— Jonathan H. Wage (@jwage) February 13, 2018

Optimizing colinodell/json5 with @blackfireiohttps://t.co/nwFI5d9AHN #php #performance

— 👨‍💻 Colin O'Dell (@colinodell) January 14, 2018

With #Symfony 3.4/4.0, enabling param `container.dumper.inline_class_loader` can boost your dev env perf by 50% and your prod by +2%. For free as usual :) /cc @blackfireio pic.twitter.com/vvPoZlTZEb

— Nicolas Grekas (@nicolasgrekas) November 10, 2017

Reduced core page load by a further 30% today using @blackfireio timelines view. Killer feature in a killer tool

— Peter Ward (@petewardreiss) November 8, 2017

Conclusion¶

This is great, but we’re not done yet. The complete process of performance optimization includes checking the impact of your code changes. First by running the unit tests to confirm that nothing is broken. Then, always compare the data between the current version of the code and the patched version to validate that the fix actually solves the problem and doesn’t introduce regressions in other parts of the code.

Performance comparisons are a key feature of Blackfire; one that we will look at in depth in the next chapter.