Finding bottlenecks in your PHP code

Frequently one finds that some piece of webpage code is slowing down pageload time. Although there are many PHP libraries that one can use to benchmark the code to find bottlenecks, most of the time a quick solution is usually enough. Usually xdebug is used, but many times it is not installed on servers. The current post show a simple way to find bottlenecks in your PHP code.

Although code purists will scoff at this way of benchmarking code and would suggest using a profiler, when time is at a premium and you do not want to add any additional libraries, this usually gets the work done quickly when the target is a single remote page. Other times use any standard profiler.

The following is a very simple PHP function that logs time at pre specified locations (we will call it markers) in your code.

$fplog = fopen("logb.txt", "a+");
$lastlogtime = time();
 
function log_time($logtext)
{
    global $fplog, $lastlogtime;
    $nowtime = time();
    $diff = $nowtime - $lastlogtime;
 
    fwrite($fplog, sprintf("%-30s | %-30s | %-3d", $logtext,  date('F Y h:i:s A', $nowtime), $diff) . PHP_EOL);
    $lastlogtime = $nowtime;
}

The way to use the above function it to insert the function calls in specific locations, which will then log the time at those certain positions in a file. The following shows an example where the markers are inserted in certain locations in a PHP code.

<?php
.
.
log_time("Start");
.
.// code
.
log_time("CertainActionController");
.
..// code
.
log_time("AfterActionController");
.
..// code
.
log_time("AfterLastCodeBlock");
fwrite($fplog, PHP_EOL . "----------------------" . PHP_EOL); 
fclose($fplog);

Once the page has executed a log file will be created in the current directory with the log data. The file output will look like the following. The first column shows the marker text, which can be anything that makes sense to you in your code context. The second column is the time recorded at the marker location. The third is the important column, this shows the number of seconds elapsed since the marker before that was executed. So we can see from the below log that around 10 seconds elapsed in the code block between ‘CertainActionController’ and ‘AfterActionController. This way you can narrow down the code that is causing slow page processing.

Start                          | March 2015 02:05:26 PM         | 0  
CertainActionController        | March 2015 02:05:28 PM         | 2  
AfterActionController          | March 2015 02:05:38 PM         | 10  
AfterLastCodeBlock             | March 2015 02:05:38 PM         | 0


6 thoughts on “Finding bottlenecks in your PHP code

Comments are closed.