Profiling manually with Blackfire.io
We will start by profiling manually two PHP scripts in order to better understand how useful and powerful the Blackfire tools can be. We will use the following script, which can be found in our repository (chap2pre.php):
<?php
function getDiskUsage(string $directory)
{
$handle = popen("cd $directory && du -ch --exclude='./.*'", 'r');
$du = stream_get_contents($handle);
pclose($handle);
return $du;
}
function getDirList(string $directory, string &$du)
{
$result = getDiskUsage($directory);
$du = empty($du)
? '<br />' . preg_replace('/\n+/', '<br />', $result)
: $du;
$fileList = [];
$iterator = new RecursiveDirectoryIterator($directory, FilesystemIterator::SKIP_DOTS);
foreach($iterator as $entry) {
if (!$entry->isDir() && $entry->getFilename()[0] != '.') {
$fileList[$entry->getFilename()] = 'size is ' . $entry->getSize();
} else {
if ($entry->isDir() && $entry->getFilename()[0] != '.') {
$fileList[$entry->getFilename()] = getDirList(
$directory . DIRECTORY_SEPARATOR . $entry->getFilename(),
$du
);
}
}
}
return $fileList;
}
$du = '';
$baseDirectory = dirname(__FILE__);
$fileList = getDirList($baseDirectory, $du);
echo '<html><head></head><body><p>';
echo 'Disk Usage : ' . $du . '<br /><br /><br />';
echo 'Directory Name : ' . $baseDirectory . '<br /><br />';
echo 'File listing :';
echo '</p><pre>';
print_r($fileList);
echo '</pre></body></html>';
The script essentially lists all files contained in our repository (the directory and its subdirectories) and calculates the size of each file. Also, it gives an aggregate result of the sizes of each directory. Please browse to the following URL with Chrome to see the script's output and launch a profile using the Blackfire Companion: http://localhost:8181/chap2pre.php:
Clicking on the Blackfire icon in the upper-right toolbar will allow you to launch a profiling session
After clicking on the Profile button and waiting a few seconds, you should then have the option of clicking the View Call Graph button:
You can click on the ‘View call graph’ button to view the script’s call graph
The results should be as follows:
The script took 14.3 ms to complete its execution and five processes were created using the 'popen' function
The result shows us that this script has a real time (wall time[1]) of 14.3 ms and that the only functions with important exclusive times are stream_get_contents and popen. This is logical, as the script has to deal with disk access and possibly a lot of I/O latency. What is less logical is that the script seems to be creating five sub-processes in order to get a simple file listing.
Also, if we scroll down, we notice that SplInfo::getFilename is called sixty-seven times, which is almost twice the number of files in the directory:
The SplFileInfo::getFilename function was called 67 times
The information obtained from the profiler allows us to quickly identify which parts of our code base should become code review candidates and what to look for when reviewing them. A quick look at our code shows us that we are calling popen on every directory iteration, rather than only once at the beginning. A simple fix would be to replace these two lines of code:
function getDirList(string $directory, string &$du)
{
$result = getDiskUsage($directory);
$du = empty($du)
? '<br />' . preg_replace('/\n+/', '<br />', $result)
: $du;
[...]
The following lines of code could then be inserted in their place:
function getDirList(string $directory, string &$du)
{
$du = empty($du)
? '<br />' . preg_replace('/\n+/', '<br />', getDiskUsage($directory))
: $du;
[...]
The final adjustment would be to replace all calls to SplInfo::getFilename() with a variable containing the result of the function call. The modified script would then look as follows:
<?php
function getDiskUsage(string $directory)
{
$handle = popen("cd $directory && du -ch --exclude='./.*'", 'r');
$du = stream_get_contents($handle);
pclose($handle);
return $du;
}
function getDirList(string $directory, string &$du)
{
$du = empty($du)
? '<br />' . preg_replace('/\n+/', '<br />', getDiskUsage($directory))
: $du;
$fileList = [];
$iterator = new RecursiveDirectoryIterator($directory, FilesystemIterator::SKIP_DOTS);
foreach($iterator as $entry) {
$fileName = $entry->getFilename();
$dirFlag = $entry->isDir();
if (!$dirFlag && $fileName[0] != '.') {
$fileList[$fileName] = 'size is ' . $entry->getSize();
} else {
if ($dirFlag && $fileName[0] != '.') {
$fileList[$fileName] = getDirList(
$directory . DIRECTORY_SEPARATOR . $fileName,
$du
);
}
}
}
return $fileList;
}
$du = '';
$baseDirectory = dirname(__FILE__);
$fileList = getDirList($baseDirectory, $du);
echo '<html><head></head><body><p>';
echo 'Disk Usage : ' . $du . '<br /><br /><br />';
echo 'Directory Name : ' . $baseDirectory . '<br /><br />';
echo 'File listing :';
echo '</p><pre>';
print_r($fileList);
echo '</pre></body></html>';
Let's try profiling the new script (chap2post.php) in order to measure our improvements. Again, please browse to the following URL with Chrome to see the script's output and launch a profile using the Blackfire Companion: http://localhost:8181/chap2post.php.
The results should be as follows:
Now, the script takes only 4.26 ms to complete its execution and only one process was created using the 'popen' function
The result shows us that this script now has a wall time of 4.26 ms and that the function popen is only creating one sub-process. Also, if we scroll down, we now notice that SplInfo::getFilename is only called thirty-three times which is two times less than before:
Now, the SplFileInfo::getFilename function gets called only 33 times
These are significant improvements, especially if this script is to be called thousands of times per minute on different directory structures. A good way to make sure that these improvements are not lost in future iterations of our application's development cycle would be to automate the profiler through performance tests. We will now give a quick example of how to automate performance testing with Blackfire.io.