Debuging with PHP, Stack Traces, and Redis

A cool new trick I found with debugging pieces of code and how often they get executed. We were running into a problem where an expensive query was being called more frequently than I thought it should. This query was only found inside of a single member of a class. However, this class, which retrieves a user’s photo album, is used all over the place. So it was really hard to determine exactly where the unneeded queries being executed from.

This is where Redis comes in. I hate doing any extensive logging to disk on a production server, however sometimes you need to do some logging to track down a bug. With Redis, it instead would be logged to memory and periodically written to file. So it was very, very quick, and did not slow down anything on production.

So to log where how many times our class was being called, we used PHP’s debug_backtrace() function. This would return an array with each row holding information about the stack trace. Using this, we could identify the different parts of our program that was using our class and this SQL statement. I used Rediska as a PHP library to communicate with Redis.

So, inside of our class right before the SQL statement, I included this code:

// Get Instance of Rediska for the Debug Connection
$redis = new Rediska_Manager::get(‘debug’);

$stacktrace = debug_backtrace();

// Loop through the stacktrace
foreach($stacktrace as $k => $v)
// Unset args and object variables, since they will throw off our hash calculation.

// Start an output buffer to capture the var_dump;
$print = ob_get_contents();

// Hash what it returns, since it will the same each time for each stacktrace
$hash = md5($print);

// Increment the count
// Set the Content of the Stack Trace so it can be read later.
$redis->set(‘debug.photoAlbum.content:’.$hash, $print);

Few important lines to note. We unset ‘args’ and ‘object’ because it will unique for each function call, we just want to know where the function is being called. We then set two values to redis, one to hold the count, and another to hold the content.

Now, to read the data, I just made a PHP script:

// Get Instance of Rediska for the Debug Connection
$redis = new Rediska_Manager::get(‘debug’);
// Get all the keys matching the patern for the counts.
$keys = $redis->getKeysByPattern(‘debug.photoAlbum.count*’);

$sorted = array();
$strings = array();

$total = 0;

// loop through the keys to strip out the hash
foreach($keys as $key)
// Get the hash part
$parts = explode(‘:’, $key);
$hash = $parts[1];

$count = $redis->get(‘debug.photoAlbum.count:’.$hash);

$total += $count;

$string = “Count (“.$hash.”): “.$count.”n”

$sorted[$hash] = $count;
$strings[$hash] = $string;

// Reverse Sort by Numberic numbers
arsort($sorted, SORT_NUMERIC);

echo “Grand Total: “.$total.”nn”;

foreach($sorted as $hash => $count)
echo $strings[$hash];

A few notes, first off, the KEYS function for Redis has some limitations. Mainly, it should be used sparingly, and only for admin pruposes. The documentation explains it pretty well.

Second, this script will sort by count and print the count along with the content of the stack trace.

This helped me identify a situation where it was calling the class several times instead of just once. The bottom line is, after figuring out the problem spot, we were able to fix it, saving us several thousand expensive queries every hour. I highly recommend this technique for debugging issues on production servers. Its working well for me.

Leave a Reply

Fill in your details below or click an icon to log in: Logo

You are commenting using your account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

This site uses Akismet to reduce spam. Learn how your comment data is processed.

%d bloggers like this:
search previous next tag category expand menu location phone mail time cart zoom edit close