One thing I really like about CakePHP is that when it’s in debug mode it prints out a list of all the database queries used to generate a page, along with the time it took to run each query. This makes it really easy to find problem queries that are slowing down your site. It’s such a great feature that I wanted something similar for projects that don’t use CakePHP.

What I came up with was a LoggedPDO class that extends PHP’s PDO class. If you’re already using PDO in your project you only need to change a single line of code to enable database query logging:

// Standard PDO...
$db = new PDO($dsn, $username, $password);
// ...should be changed to
$db = new LoggedPDO($dsn, $username, $password);

And then all your database queries will be logged, timed and all information printed out at the end of each page. My code also includes a decorator for PDOStatements so any prepared statements that get executed also get logged. Below is a small sample of the code in use:

$db = new LoggedPDO("mysql:dbname=test;host=localhost", "root");
$results = $db->query("SHOW TABLES");
$tables = $results->fetchAll(PDO::FETCH_COLUMN);
foreach($tables AS $table) {
	$statement = $db->prepare("DESCRIBE :table");
	$statement->bindParam(":table", $table, PDO::PARAM_STR);
	$results = $statement->execute();
	$columns = $statement->fetchAll(PDO::FETCH_ASSOC);
}

Which would output:

Full code for the both the LoggedPDO and LoggedPDOStatement classes is below:

/**
* Extends PDO and logs all queries that are executed and how long
* they take, including queries issued via prepared statements
*/
class LoggedPDO extends PDO
{
	public static $log = array();

	public function __construct($dsn, $username = null, $password = null) {
		parent::__construct($dsn, $username, $password);
	}

	/**
	 * Print out the log when we're destructed. I'm assuming this will
	 * be at the end of the page. If not you might want to remove this
	 * destructor and manually call LoggedPDO::printLog();
	 */
	public function __destruct() {
		self::printLog();
	}

	public function query($query) {
		$start = microtime(true);
		$result = parent::query($query);
		$time = microtime(true) - $start;
		LoggedPDO::$log[] = array('query' => $query,
				                  'time' => round($time * 1000, 3));
		return $result;
	}

	/**
	 * @return LoggedPDOStatement
	 */
	public function prepare($query) {
		return new LoggedPDOStatement(parent::prepare($query));
	}

	public static function printLog() {
		$totalTime = 0;
		echo '<table border=1><tr><th>Query</th><th>Time (ms)</th></tr>';
		foreach(self::$log as $entry) {
			$totalTime += $entry['time'];
			echo '<tr><td>' . $entry['query'] . '</td><td>' . $entry['time'] . '</td></tr>\n';
		}
		echo '<tr><th>' . count(self::$log) . ' queries</th><th>' . $totalTime . '</th></tr>\n';
		echo '</table>';
	}
}

/**
* PDOStatement decorator that logs when a PDOStatement is
* executed, and the time it took to run
* @see LoggedPDO
*/
class LoggedPDOStatement {
	/**
	 * The PDOStatement we decorate
	 */
	private $statement;

	public function __construct(PDOStatement $statement) {
		$this->statement = $statement;
	}

	/**
	* When execute is called record the time it takes and
	* then log the query
	* @return PDO result set
	*/
	public function execute() {
		$start = microtime(true);
		$result = $this->statement->execute();
		$time = microtime(true) - $start;
		LoggedPDO::$log[] = array('query' => '[PS] ' . $this->statement->queryString,
				                  'time' => round($time * 1000, 3));
		return $result;
	}
	/**
	* Other than execute pass all other calls to the PDOStatement object
	* @param string $function_name
	* @param array $parameters arguments
	*/
	public function __call($function_name, $parameters) {
		return call_user_func_array(array($this->statement, $function_name), $parameters);
	}
}