To profile the code base of a large-scale website I wrote a simple helper class to determine processing times of certain code sections. In general I find XDebug and KCachegrind very helpful for code profiling but this has proven very helpful for realtime profiling.

<?php
// Define TIMER_RUNTIME_START for total script timing
// This will also automatically be defined on inclusion of
// class_timer.php
define('TIMER_RUNTIME_START', microtime(true));

require_once('class_timer.php');
$timer = Timer::singleton('/tmp/logfile', array('precision' => 2));

// Timers can be nested too
$timer->start('wrapper_timer');

$timer->start('first_timer');
// Do something slow
sleep(1);
$timer->stop('first_timer');

$timer->start('second_timer');
// Do something slow
usleep(200000);
$timer->stop('second_timer');

$timer->stop('wrapper_timer');
?>

The output can be logged to a dedicated file or the standard error log. Here the output of the example above:

=== 2012-11-29 10:05:46 ===
wrapper_timer => total 1.20, count 1, max. 1.20, avg. 1.20
first_timer => total 1.00, count 1, max. 1.00, avg. 1.00
second_timer => total 0.20, count 1, max. 0.20, avg. 0.20
=== 2012-11-29 10:05:46 ===

It is also possible to log the percentage of the total script execution time for each section.

To do so set the percent flag

$timer = Timer::singleton('/tmp/logfile', array('percent' => true));

The output will look something like this:

=== 2012-11-29 10:32:14 ===
wrapper_timer => total 99.24%, count 1, max. 99.24%, avg. 99.24%
first_timer => total 82.62%, count 1, max. 82.62%, avg. 82.62%
second_timer => total 16.57%, count 1, max. 16.57%, avg. 16.57%
=== 2012-11-29 10:32:14 ===

To get the most precise output define the TIMER_RUNTIME_START constant as early as possible in the script:

define('TIMER_RUNTIME_START', microtime(true));

If you don’t define this constant it will be automatically defined on inclusion of class_timer.php.

Download the code here.