24 Nov 2010

PHP: Easy integrated benchmarking

Source code

When I began developing PHP I found the biggest stumbling block for me was learning the best practices and many nuances for greater performance, especially when querying a database. I found that I could smash out functional PHP for proof of concept purposes, but when it came to optimising my code for release and I had trouble finding exactly what functions and queries were slowing things down.

The solution

I found a great little benchmarking solution as a comment by ‘godomo’ in the PHP manual by accident. It’s great because it’s an integrated solution that is simple to use and outputs it’s benchmark data in the generated HTML as a comment. After implementing this solution I was able to track down optimise troublesome code much more rapidly. I’ve since modified the original code to make the output more legible. I include this benchmark solution in most PHP apps by default now with a simple boolean switch to turn it on during testing, and then disable it for release.

Here’s my modified version of the benchmarking function, it’s use will become clear when I later explain how it is implemented…

 

function mini_bench_to($arg_t)
{
   // Get the current php file without path...
   $currentFile = $_SERVER["SCRIPT_NAME"];
   $parts = Explode('/', $currentFile);
   $currentFile = $parts[count($parts) - 1];

   // Report header...
   $report = "\n\n<!-- ";
   $report .= str_pad(' Server benchmark results for ' .
         $currentFile . ' (' . date("d M Y H:i:s") . ') ' ,
         118, '~', STR_PAD_BOTH) . "~~~~~\n\n";

   // Report body...
   $tttime = end($arg_t) - $arg_t['START'];

   // Use the START item as our reference...
   $prv_cle = 'START';
   $prv_val = $arg_t['START'];

   foreach ($arg_t as $cle=>$val)
   {
      if ($cle != 'START')
      {
         // Find the difference in time from the START...
         $sec_t = str_pad(number_format(($val - $prv_val),
               3, '.', ',') . ' sec', 12, ' ', STR_PAD_LEFT);

         // Find the difference in percentage from the START...
         $prcnt_t = str_pad(number_format(((($val - $prv_val) / $tttime) * 100),
               1, '.', ',') . ' %', 12, ' ', STR_PAD_LEFT);

         // Add this to the report.
         $report .= '  ' . str_pad($prv_cle, 50) .
               str_pad($cle, 50) .
               $sec_t .
               $prcnt_t .
               "  \n";

         $prv_val = $val;
         $prv_cle = $cle;
      }
   }

   // Report footer...
   $report .= "\n  " . str_pad('TOTAL TIME', 100) .
         str_pad(number_format($tttime, 3, '.', ',') .
         ' sec', 12, ' ', STR_PAD_LEFT) . "     100.0 %  \n";

   $report .= "\n~~~~" . str_pad('', 120, '~') . ' -->';

   return $report;
}

Implementation

The first thing we need to do is create an array to store the benchmark data. Once this is done we can start adding ‘milestones’. The first benchmark addition needs have ‘START’ as it’s key. This will be found by the mini_bench() function and it’s time value will be used as a reference for all other benchmark items. The best place for this is in the __construct() function of the app, like so…

// Declare a variable (array) to hold our benchmark milestones.
public $benchmark;

public function __construct()
{
   // Enable benchmarking.
   define('BENCHMARK', TRUE);

   if (FALSE != BENCHMARK)
   {
      // The first benchmark index *must* be 'START'!
      $this->benchmark['START'] = microtime(TRUE);
   }
}

The whole point of this benchmarking solution is not only to get a total page generated time, but to break this up in to milstones along to way to see what parts of the application are the most expensive and could do with optimisation. To do this we simply add more items to our benchmark array. The array item key can be any brief description you like. I’ve found it useful in large applications to include the class and function name. The array item value is simply another microtime(TRUE) call giving us a Unix time in milliseconds.

Here’s how it’s done…

public someFunction()
{
   if (FALSE != BENCHMARK)
   {
      $this->benchmark[__CLASS__ . '::' . __FUNCTION__ . ' start'] = microtime(TRUE);
   }

   // Do stuff here...

   if (FALSE != BENCHMARK)
   {
      $this->benchmark[__CLASS__ . '::' . __FUNCTION__ . ' end'] = microtime(TRUE);
   }
}

You can add as many benchmarks as you like as long as the key is unique, so be careful when using inside a loop (try adding a count/iterator value)!

At the end of the app, you’ll want to report back all the data collected. The benchmark should be finalised as late as possible. Here we have it in the __destruct() function which is called when the PHP app finishes.

We add a final item to the benchmark array (called ‘FINISH’) and then call our mini_bench() function to output the data as a HTML comment on the generated page.

public function __destruct()
{
   if (FALSE != BENCHMARK)
   {
      // Add the last benchmark item.
      $this->benchmark['FINISH'] = microtime(TRUE);

      // Format and output benchmark data.
      echo $this->mini_bench($this->benchmark);
   }
}

The result

Here’s a simple example of what it looks like. Neat and legible. 🙂

This is output as a HTML comment at the end of the page source.

<!-- ~~~~~~~~~~~~~~~~~~~~~~~~~~~ Server benchmark results for alerts.php (24 Nov 2010 18:52:51) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

  START                                             AlertsManager::showMainMenu start                    0.016 sec       4.3 %
  AlertsManager::showMainMenu start                 AlertsManager::showMainMenu check DAQ                0.000 sec       0.0 %
  AlertsManager::showMainMenu check DAQ             AlertsManager::showMainMenu check licence            0.348 sec      91.0 %
  AlertsManager::showMainMenu check licence         AlertsManager::showMainMenu table                    0.006 sec       1.7 %
  AlertsManager::showMainMenu table                 AlertsManager::showMainMenu end                      0.010 sec       2.7 %
  AlertsManager::showMainMenu end                   FINISH                                               0.001 sec       0.3 %  

  TOTAL TIME                                                                                             0.382 sec     100.0 %  

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ -->

Further reading

The original benchmark code by ‘gomodo’

About the Author:

Hardware and software engineer with experience in product development and building automation. Product Manager at NEX Data Management Systems, based out of Brisbane, Australia.

Leave a Reply

*