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:
| Query | Time (ms) |
|---|---|
| SHOW TABLES | 0.174 |
| [PS] DESCRIBE :table | 0.06 |
| [PS] DESCRIBE :table | 0.032 |
| 3 queries | 0.266 |
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);
}
}