PHP : Web Basics - [8.20] Logging Debugging Information

8.20.1 Problem

You want to make debugging easier by adding statements to print out variables. But, you want to easily be able to switch back and forth from production and debug modes.

8.20.2 Solution

Put a function that conditionally prints out messages based on a defined constant in a page included using the auto_prepend_file configuration setting. Save the following code to debug.php:

// turn debugging on
define('DEBUG',true);

// generic debugging function
function pc_debug($message) {
    if (defined(DEBUG) && DEBUG) {
        error_log($message);
    }
}

Set the auto_prepend_file directive in php.ini:

auto_prepend_file=debug.php

Now call pc_debug( ) from your code to print out debugging information:

$sql = 'SELECT color, shape, smell FROM vegetables';
pc_debug("[sql: $sql]"); // only printed if DEBUG is true
$r = mysql_query($sql);

8.20.3 Discussion

Debugging code is a necessary side-effect of writing code. There are a variety of techniques to help you quickly locate and squash your bugs. Many of these involve including scaffolding that helps ensure the correctness of your code. The more complicated the program, the more scaffolding needed. Fred Brooks, in The Mythical Man-Month, guesses that there's "half as much code in scaffolding as there is in product." Proper planning ahead of time allows you to integrate the scaffolding into your programming logic in a clean and efficient fashion. This requires you to think out beforehand what you want to measure and record and how you plan on sorting through the data gathered by your scaffolding.

One technique for sifting through the information is to assign different priority levels to different types of debugging comments. Then the debug function prints information only if it's higher than the current priority level.

define('DEBUG',2);

function pc_debug($message, $level = 0) {
    if (defined(DEBUG) && ($level > DEBUG) {
        error_log($message);
    }
}

$sql = 'SELECT color, shape, smell FROM vegetables';
pc_debug("[sql: $sql]", 1); // not printed, since 1 < 2
pc_debug("[sql: $sql]", 3); // printed, since 3 > 2

Another technique is to write wrapper functions to include additional information to help with performance tuning, such as the time it takes to execute a database query.

function getmicrotime(){
    $mtime = microtime();
    $mtime = explode(' ',$mtime);
    return ($mtime[1] + $mtime[0]);
}
 
function db_query($sql) {
    if (defined(DEBUG) && DEBUG) {
         // start timing the query if DEBUG is on
         $DEBUG_STRING = "[sql: $sql]<br>\n";
         $starttime = getmicrotime();
    }

    $r = mysql_query($sql);

    if (! $r) {
        $error = mysql_error();
        error_log('[DB: query @'.$_SERVER['REQUEST_URI']."][$sql]: $error");
    } elseif (defined(DEBUG) && DEBUG) {
        // the query didn't fail and DEBUG is turned on, so finish timing it
        $endtime = getmicrotime();
        $elapsedtime = $endtime - $starttime;
        $DEBUG_STRING .= "[time: $elapsedtime]<br>\n";
        error_log($DEBUG_STRING);
    }

    return $r;
}

Here, instead of just printing out the SQL to the error log, you also record the number of seconds it takes MySQL to perform the request. This lets you see if certain queries are taking too long.

The getmicrotime( ) function converts the output of microtime( ) into a format that allows you to easily perform addition and subtraction upon the numbers.