coderholic

PHP Profile Class

Profiling is a important part of software development, allowing you to find bottlenecks in your application and discover areas that would benefit from optimisation. In PHP a common technique is to calculate the total time to render a page. This can be achieved using the microtime function:

<?php
$startTime = microtime(true);

// normal page code here

$time = microtime(true) - $startTime;
echo "<!-- Page generation time: {$time} seconds -->";
?>

This simple approach is a a great way to find out how long certain pages are taking to load. Sometimes, however, you want more granular profiling information. That's why I created a Profile class, which records the execution time of a given method. Here's how to use it:

$p = new Profile();
$time = $p->profile("myClassName", "methodName", array("arg1", "arg2"));

You can also pass in an optional fourth argument, which specifies how many times to run the given method. After running it multiple times you can call the Profile::printDetails() method to view the total time, average invocation time, and the maximum single invocation time. Below is a simple example:

<?php
include("Profile.php");

/**
 * Test class just for the purposes of demonstration
 */
class Test {
    public function add($a, $b) {
        // add the numbers together 100 times
        for($i = 0; $i < 100; $i++) {
            $c = $a + $b;
        }
    }
}

$p = new Profile();
$p->profile("Test", "add", array(1, 2), 1000);
$p->printDetails();
?&gt;

If you run the above code you'll see the following output:

Test::add(1, 2) was invoked 1000 times Total duration: 0.0447s Average duration: 0s Worst duration: 0.002s

The code listing for the Profile class is below, with some of the comments removed for the sake of brevity. A fully commented version is available for download.

&lt;?php
/**
 * Class to time the execution of method calls.
 *
 * @author Ben Dowling - www.coderholic.com
 */
class Profile {
    /**
     * Stores details about the last profiled method
     */
    private $details;
    
    public function __construct() {}

    /**
     * @param classname string 
     * @param methodname string
     * @param methodargs array
     * @param invocations int The number of times to call the method
     * @return float average invocation duration in seconds
     */
    public function profile($classname, $methodname, $methodargs, $invocations = 1) {
        if(class_exists($classname) != TRUE) {
            throw new Exception("{$classname} doesn't exist");
        }
        
        $method = new ReflectionMethod($classname, $methodname);
        
        $instance = NULL;
        if(!$method-&gt;isStatic())         {
            $class = new ReflectionClass($classname);
            $instance = $class-&gt;newInstance();
        }
        
        $durations = array();
        for($i = 0; $i &lt; $invocations; $i++) {
            $start = microtime(true);
            $method-&gt;invokeArgs($instance, $methodargs);
            $durations[] = microtime(true) - $start;
        }

        $duration["total"] = round(array_sum($durations), 4);
        $duration["average"] = round($duration["total"] / count($durations), 4);
        $duration["worst"] = round(max($durations), 4);   
        
        $this-&gt;details = array(  "class" =&gt; $classname,
                                "method" =&gt; $methodname,
                                "arguments" =&gt; $methodargs,
                                "duration" =&gt; $duration,
                                "invocations" =&gt; $invocations);
        
        return $duration["average"];  
    }
    
    /**
     * @return string
     */
    private function invokedMethod() {
        return "{$this-&gt;details["class"]}::{$this-&gt;details["method"]}(" .
             join(", ", $this-&gt;details["arguments"]) . ")"; 
    }
    
    /**
     * Prints out details about the last profiled method
     */
    public function printDetails() {
        $methodString = $this-&gt;invokedMethod();
        $numInvoked = $this-&gt;details["invocations"];
        
        if($numInvoked == 1) {
            echo "{$methodString} took {$this-&gt;details["duration"]["average"]}s\n";
        }

        else {
            echo "{$methodString} was invoked {$numInvoked} times\n";
            echo "Total duration:   {$this-&gt;details["duration"]["total"]}s\n";
            echo "Average duration: {$this-&gt;details["duration"]["average"]}s\n";
            echo "Worst duration:   {$this-&gt;details["duration"]["worst"]}s\n";
        }
    }
}

?&gt;
Posted on 24 Sep 2008
If you enjoyed reading this post you might want to follow @coderholic on twitter or browse though the full blog archive.