MySQL debugging in PHP - If you work with MySQL and PHP and dread the often insufficient error reporting that MySQL does using mysql_error(), this article might help. It describes a few simple routines, which can trace down the origins of faulty or slow SQL-code inside your PHP.

If you work with MySQL and PHP and dread the often insufficient error reporting that MySQL does using mysql_error(), this article might help. It describes a few simple routines, which can trace down the origins of faulty or slow SQL-code inside your PHP.

By Martin Joergensen

When I first started coding in PHP using MySQL as the primary database, I was very meticulous about using all the MySQL-functions that PHP offers on every call. I would use mysql_query() every time and check for errors using mysql_error() after each call.

Like many others before me, I soon realized that I needed to avoid coding the same lines over and over again, and decided to create a small function that took care of the query and error handling. For ease of use and in order to save a lot of typing, I simply called the function m() for ease of typing, and I have used this name and the offspring of the same function in many projects since.

A small complex <

Over the years the little function has become a small complex of functions, which serves several purposes. It is now able to:

- execute the query and return the result (sic!)
- report and trace MySQL errors
- time database calls
- report timings in numbers and visuals

I will cover these possibilities in a moment, but just take this opportunity to explain why I made my own little library in stead of using an existing database abstraction class.

Much too capable <

Now, I know that there are many excellent database libraries and abstraction classes out there, but honestly: most of them were much too capable (read: complex) for what I needed back when. Many of these libraries have some excellent functions for doing what I do – and much more. All I needed in the first place was a simple function, which returned the result of a query and did a bit of household processing if an error occurred.

I also know that genuine debuggers are more and more common in many modern development environments, but call me old fashioned – I still use an intelligent editor and debug “manually” – and never really found an IDE and debugger combo, which suits me.

And regarding SQL-timing, there are also other means, like tailing the SQL-log on the server or using the SQL command SHOW PROCESSLIST. But sometimes you don’t have access to the log. Other sites may also be using the same database or several users can be drawing on the same tables in a live database. All this can severely complicate following the calls of your single process while you are testing.

So I have cooked my own sauce, and with just exactly the ingredients that I need.

Intelligent error trapping <

If you use mysql_error() for error reporting in your applications you know how frustrating its lack of precision can be. First of all it just reports a very brief message and in most cases a small chunk of the SQL with little indication of the real cause and location of the error. In the best case it actually does hint the nature and origin of the error. In the worst case it’s close to useless.

My first incarnation of this routine did something very simple. It printed the whole SQL-query as a supplement to the snippet that mysql_error() gives you. After that I let the routine die() and the whole application halt. I could then see if I could find the error in the complete SQL-statement.

But opposite most errors reported by PHP, the mysql_error() routine does not tell you where in your code the error has occurred. Since there is likely to be many almost identical SQL-queries in an application, hunting down the origin of the error can sometimes be a chore.

Tracing the origins <

Luckily PHP has had a tracing function called debug_backtrace() since version 4, and with this function at hand, we can trace the origins of the SQL-error.
By calling the function, we get an array with information on the stack of function calls.
I have created a routine called backtrace(), which I call in order to dump function trace information.
In the event of an SQL-error, the SQL-statement and mysql_error() are printed. Then I call backtrace(), which shows all the functions called in this process with itself and m() as the two first.

What is interesting is what happened before that, and the function backtrace() will trace the call stack all the way to the first function call.
backtrace() returns the name of the functions, their arguments, and from which file and line the functions were called, all organized in a small HTML-table, ready to print on the screen.

This enables you to locate the root of the call, which eventually caused the SQL-error, and this can be very helpful in pruning out the error.

Timing queries <

One thing is SQL that downright fails. In most cases a failure will be so severe that the program malfunctions or even halts.
SQL that performs poorly is a lot less obvious and a lot harder to locate. Complex pages with many SQL-queries can often lead to slow response times, and I have many a time been frustrated by the hardships of finding the slow SQL-statement and trimming it or the tables involved.

Since I have already canalized all SQL-queries through the same function, it is logical to locate a timing facility here.

The timing relies on the PHP-function microtime(), which takes a timestamp with a precision of thousands of a second.
When this routine is in place, you can indicate to your script that you want timing by adding a time_db argument to the URL like in my_mysql_test.php?time_db=1.
In this example a timestamp will be saved before performing the SQL and right after. Then we do a bit of math and convert the difference to a floating number.
If the size of this number is larger than the time_db-argument, the time is saved in a global array called times.

I have found it convenient to be able to set a lower limit for the timings. That will permit you to screen only the really slow routines. Set the number to -1 (minus one) to get all times.

So my_mysql_test.php?time_db=0.1 will harvest all SQL times which are more than one tenth of a second. my_mysql_test.php?time_db=-1 will show everything.

What’s the score? <

All the timing routine does is to save the times, so when the script is done, we want to present the results on screen.
The function mysql_digest_times() will do just that. Feed it the global timings array $mysql_times and the function will traverse it and present each SQL-statement in a table row with a measure of all the times it has run.
I have added a small pseudo bar graph in order to have something visual to pinpoint the really slow routines, which are usually the ones you are after. The longer the bar, the slower the SQL.

Dogma debugging <

I know this is not rocket science. The routines illustrated here are all quite simple, but have aided me time and time again in my development work. Tracing errors and optimizing code is still something that we spend a lot of time doing and every reduction here is welcome.

I hope you find them as useful as I have.

Code <

Below you will find the code.

First the library. I have called the file mysql_query.lib.php.

<?php

// *******************************************************************
// mysql_query.lib.php - a MySQL query library with error reporting and timer
// Developed by Martin Joergensen, (c) 2005
// martin@globalflyfisher.com, http://globalflyfisher.com
// This code is licensed under the Noncommercial Creative Commons License
// You are not only encouraged to use it noncommercially but also to develop it
// Please credit me if you use or redistribute it

// The mysql_query substitute m()
function m($query)
    {
    global $mysql_times, $mysql_times_sum;

    // Start the timer if the user wants it before doing anything else
    if ($_GET['time_db']) {
        $start=microtime();
        }

    // Run the query and save results
    $result=@mysql_query($query);

    // Check for errors
    $error=mysql_error();
    if ($error) {
        // Print the error and the query
        echo $error.'<br />'.$query.'<br />'.
            // Trace the function to reveal the origin of the error
            backtrace();
        // Stop the program - optional
        die();
        }

    // Stop the timer and do the math if the user wants it
    if ($_GET['time_db']) {

        // Split the Unix timestamps in secs and hundreds
        $end=split(' ', microtime());
        $start=split(' ', $start);

        // Calculate the differences
        $res[0]=$end[0]-$start[0];
        $res[1]=$end[1]-$start[1];

        // Add and convert the time to floating seconds
        $res=(float)$res[1]+(float)$res[0];

        // Only report if the result is bigger than the limit
        if ($res>$_GET['time_db']) {
            // Add to the global array of results
            $mysql_times[$query][]=$res;
            }

        // Add to the global sum
        $mysql_times_sum+=$res;
        }

        // Return the MySQL-result
        return $result;
        }


// Digest the array of database timings
function mysql_digest_times($mysql_times)
    {
    if (!is_array($mysql_times))
        // No results were recorded
        return 'None<br />';

    // Create a table with the results
    $return='<table>';
    // Traverse the array
    foreach($mysql_times as $query=>$times) {
        // Return a row for each query
        $return.='<tr valign="top" style="background-color : #cccccc">'.
            '<td>'.$query.'<br />';
        // Show time and "graph" for each timing for that query
        foreach($times as $key=>$seconds) {
            $return.=$seconds.'<br />'.
                substr(str_repeat(':', 100).'>>', 0, round($seconds*200)).'<br />';
            }
        // Finish row
        $return.='</td></tr>';
        }
    return $return.'</table>';
    }


// Trace the origins of a function call
function backtrace()
    {
    // Output everything in a table
    $return='<table><tr style="font-weight : bold; background-color : #cccccc">
        <td>Function</td><td>Args</td><td>File</td><td>Line</td></tr>';

    // Get the backtrace information
    $debug_array = debug_backtrace();

    // Run through the array
    foreach($debug_array as $key=>$data) {
        $return.='<tr valign="top" style="background-color : #eeeeee">'.
            '<td>'.$data['function'].'</td><td>';
        // Show list of function arguments
        if ($data['args']) {
            foreach($data['args'] as $key=>$arg) {
                $return.=$arg.'<br />';
                }
        } else
            $return.='&nbsp;';
        $return.='</td>';

        // Show file name and line number
        $return.='<td>'.$data['file'].'</td>'.
            '<td>'.$data['line'].'</td></tr>';
        }
    return $return.'</table>';
    }

?>

Below you find a small example of the usage of the library.

<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.0 Transitional//EN">
<html>
<head>
<title>Mysql error tracking</title>
</head>
<body>

<?php
// Include our little routine
include('mysql_query.lib.php');

// A function with an SQL-statement that will fail
function nonsense()
    {
    $result=m('SELECT * FROM nonsense');
    }

// Connect to the database - change to your own settings
$db=mysql_connect('localhost', 'user', 'password');
mysql_select_db('mysql', $db);

// Do some SQL mumble-jumble reading on the mysql-database - DON'T WRITE!
$result=m('SHOW TABLES FROM mysql');
while ($table=mysql_fetch_object($result)) {
    $table_result=m('SELECT * FROM '.$table->Tables_in_mysql);
    m('SELECT * FROM help_topic');
    }

// Show timing information
echo 'Sum: '.$mysql_times_sum.'<br />'.mysql_digest_times($mysql_times);

// Try but fail using our routine
echo nonsense();
?>
</body>
</html>