Debugging and Profiling MySQL Performance with PHP

We already talked about PHP performance profiling by using the handy built-in xdebug profiler and passing the XDEBUG_PROFILE parameter.  You can find the original blog article here.  But, that method does not give you and easy way to view the SQL calls you are making or the individual performance of those calls.  To add a SQL performance profile to your database calls we will create a wrapper class that will intercept each query and store the timing information and call that is being made.  This wrapper is a drop in replacement for the original mysqli calls.

<?php

/** - Database debug helper

 * This is a wrapper class for FirePHP or other logging system
 *
 * USAGE: use debug_mysql in place of mysqli:
 * global $is_dev;
 * $is_dev = true;
 * global $debug_sql_flag;
 * $debug_sql_flag = true;
 * $dbHandle = new debug_mysql("host_ip", "user", "pw", "dbname");
 * $dbHandle->set_charset("utf8"); //optional
 * $sql ="SELECT * FROM tablename";
 * $query_result = $dbHandle->query($sql, __FILE__, __METHOD__, __LINE__);
 *
 * @author sbossen
 */

class debug_mysql extends mysqli {

    const log_file = "/var/log/firephp.log";

    public function query($sql, $file = "", $method = "", $line = "") {

        global $is_dev; //indicates if this is a development system
        global $debug_sql_flag; //indicates if we are processing debug log events

        if ($is_dev) {
            $query_start = microtime(true);
            $result = parent::query($sql);
            $query_end = microtime(true);
            $query_time = $query_end - $query_start;

            if ($debug_sql_flag) {
                if ($query_time > 10) {
                    $speed = "slow";
                } else {
                    $speed = "normal";
                }
                if (!$result) {
                    $err = "ERROR: $this->error";
                } else {
                    $err = "Ok";
                }
                $db = $this->get_database_name();
                self::log_to_file("QUERY: $query_time ms, $speed, $db, $sql, $err", $file,$method,$line);
            }
            return $result;
        } else {
            //pass original query through if this is a production system
            return parent::query($sql);
        }
    }

    /**
     * Get name of the database that is currently selected
     * @return string - database name
     */
    public function get_database_name() {
        $str = "{unknown db}";
        if ($result = parent::query("SELECT DATABASE()")) {
            $row = $result->fetch_row();
            $str = $row[0];
            $result->close();
        }
        return $str;
    }

    /**
     * @param type $str - message to output
     * @param type $file - file that the method was called from
     * @param type $method - method that was called
     * @param type $line - line method was called from
     */
    public static function log_to_file($str, $file = "", $method = "", $line = "") {
        file_put_contents(self::log_file, $file."::".$method."[".$line."] - \"".$str."\"\n", FILE_APPEND);
    }

}
?>

This gives you a log file that stores all of your SQL commands and can be imported as a CSV file into Excel for sorting or other analysis.  SQL error messages are captured along with the location in the code the call was made from (provided you pass them along

If you are running the server on linux you can simply open a shell session and run:

tail -f /var/log/firephp.log

You can watch this terminal window show all your queries along with the time it takes to execute each query.  Any SQL errors that are found will display along with the error information.  This helps for quick debugging if you just want to find out if your queries are running properly.

Instead of displaying to a log file, it can be useful to output the log to FirePHP.  FirePHP allows you to display debug information to your Firebug console through the Firefox web browser.  It can certainly be handy if you don't want to or can't open up a shell connection.  Install FirePHP using pear as described on the FirePHP website and install the FirePHP Firefox extension to your browser.

To display to FirePHP instead of a file, replace the log_to_file() function with the code below.  This way you can have SQL code show right in your browser.

public static function log_to_file($str, $file = "", $method = "", $line = "") {
    $firephp = FirePHP::getInstance(true);
    $firephp->log($file."::".$method."[".$line."] - \"".$str."\"");
}

Always be careful not to show debug information on a production system.  At best it is a sloppy practice and at worst it can reveal sensitive system data.