Day 4 - Your First Profile

Time to get our hands dirty! In this chapter, we are going to profile a real application and use Blackfire's web interface to understand its behavior and find some code optimizations.

The project we are going to work on is an Open-Source PHP project, GitList:

GitList is an elegant and modern web interface for interacting with multiple git repositories.

According to the Git repository, GitList "allows you to browse repositories using your favorite browser, viewing files under different revisions, commit history, diffs. It also generates RSS feeds for each repository, allowing you to stay up-to-date with the latest changes anytime, anywhere. GitList was written in PHP, on top of the Silex microframework and powered by the Twig template engine."

For the purpose of this tutorial, we have installed GitList on a demo server at http://gitlist.demo.blackfire.io/ and set up a repository for Twig there. Of course, Blackfire has also been installed and configured.

Our goal is to find bottlenecks in the GitList source code and, if we find any, propose changes to optimize its performance.

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 or Google+ account.

Next, be sure you are using Google Chrome and have the Blackfire extension installed. We will use this extension to trigger our GitList profiles:

Installed Upgrade available Not installed

Install the Blackfire Companion from the Google Chrome Web Store:

We are now ready to start our first profiling session!

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

/docs/gitlist-profile-companion.png

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:

/docs/gitlist-profile-progressbar.png

Note

If anything does not work as described in this tutorial, do not hesitate to contact us.

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:

/docs/gitlist-profile-summary.png

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

  • 13.9ms: the time it took for PHP to generate the GitList homepage;
  • 4.54 ms: the I/O time;
  • 9.4ms: the CPU time;
  • 1.57 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.

Blackfire only profiles the PHP code executed on the server side or back-end. It does not profile the front-end (JavaScript execution, DOM rendering, ...).

Hooray! You've just generated your first profile.

Isn't that a major security issue? This would be a concern any other time, but we have specially configured the security on this server to allow anyone to run a profile, for the purpose of this tutorial. Rest assured, this would never be the case on your own servers. Blackfire's authentication and authorization mechanism is out of the scope of this chapter, but we will cover it later on in this series.

It took almost 14ms 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, http://gitlist.demo.blackfire.io/Twig/. Load this page in your browser and use the Google Chrome 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 quickly 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:

/docs/gitlist-magnifying-glass.png

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:

/docs/gitlist-gitter-getversion.png

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 easily 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:

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.