Coderholic

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();
?>

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.

<?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->isStatic()) 		{
			$class = new ReflectionClass($classname);
			$instance = $class->newInstance();
		}

		$durations = array();
		for($i = 0; $i < $invocations; $i++) {
			$start = microtime(true);
			$method->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->details = array(	"class" => $classname,
							   	"method" => $methodname,
							   	"arguments" => $methodargs,
						 		"duration" => $duration,
								"invocations" => $invocations);

		return $duration["average"];
	}

	/**
	 * @return string
	 */
	private function invokedMethod() {
		return "{$this->details["class"]}::{$this->details["method"]}(" .
			 join(", ", $this->details["arguments"]) . ")";
	}

	/**
	 * Prints out details about the last profiled method
	 */
	public function printDetails() {
		$methodString = $this->invokedMethod();
		$numInvoked = $this->details["invocations"];

		if($numInvoked == 1) {
			echo "{$methodString} took {$this->details["duration"]["average"]}s\n";
		}

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

?>