Introduction

In our company, code reviews play an integral part in the development process for making quality software. We opt for a mentor style approach with Wufoo, where a developer works on a segment for a period of time and then passes it up to a more experienced developer for review. We really like this approach because it means more developers become familiar with the foundation of different code level services. More importantly, they act as an additional safeguard against security holes, memory leaks, poor queries and heavy file structures. Unfortunately, these reviews are also very time consuming and in a small team can sometimes be an inconvenience to the reviewer — another developer with their own todo list to accomplish.

Given that all reviews check against the same list of requirements, we’ve found ourselves repeating the same tasks over and over again. We spend a lot of time echoing queries, memory stats and objects to the browser just to see how they are being used in the code. To reduce this repetition, we invested some time creating something we’ve called the PHP Quick Profiler—we call it PQP for short. It’s a small tool (think Firebug for PHP) to provide profiling and debugging related information to developers without needing them to add a lot of programmatic overhead to their code. Now, we only need to toggle one config setting to true and our reviewers have access to an automated tool to help create a faster and more consistent review experience. Since anyone can use it, PQP also gives the initial developer an idea of where their code stands before the review.

We’ve been using PQP for a while now with Wufoo. It’s been so useful that we decided to take some time to package everything, write out some documentation and offer it up for anyone to use.

See it in Action

We’ve created an online example showing a landing page with PQP turned on. The profiler contains a 5 tabbed interface that presents pages for logging messages, measuring execution time, analyzing queries, revealing memory used and showing the files included.

Thanks to Kevin’s help, who did a great job of designing and encapsulating the interface, there’s no need here to add links to external CSS files or Scripts to make it show up right. When included on a page in PHP, PQP automatically inserts the markup, CSS and JavaScript needed to make the interface show up and just work. PQP should work with Internet Explorer 6 and up, Firefox and Safari.

Getting Started

We’ve provided a zip file which contains the entire setup for PQP and some basic instructions for installation.

Download: pqp.zip

Once you’ve downloaded the zip, upload the contents to a PHP enabled web server. Navigating to the root directory in your browser will show the same online example we linked to above. At this point, each tab should work except for the database tab, which requires some additional configuration.

Once you get the example working, the next step would be integration with your own project. It’s important to note that dropping the folder into your own project directory will not work. This is because 5 different aspects of the code are being looked at, and you may handle those situations differently than we do. That said, integration is pretty straightforward, and by following the guidelines for each section below, you should be up and running in no time.

Using It In Your Code

The easiest way to make PQP work in your own code is to include PhpQuickProfiler.php into the page you want to see it on. That alone will enable the console, memory and file logging. Speed and database logging take a bit more work, which we’ll cover later. Now, enabling the default logging is great, but nothing will display to the screen by just including the file. To display to the screen, a bit more knowledge on what’s happening is required.

As code is being executed, details are being logged and analyzed in PQP . Once the code is finished, PQP finishes up also, and displays the output to the screen. The tricky part is knowing when the code is finished, since in an ideal world this tool would work with as little developer input as possible. In this example, we determine that the code has finished by looking at when the parent object runs its destructor. So a timeline would be:

Landing Page constructor declares an instance of PhpQuickProfiler .

. Landing Page executes all needed code.

Landing Page destructor tells the PhpQuickProfiler to cleanup and display output.

Of course, this setup would cause PQP to always display, which isn’t ideal for production. To make it more useful, we created a Config flag in our code ( debugMode = true ) that checks to make sure it is set to true before displaying. Below is a sample class that can perform the steps we just covered:

class ExampleLandingPage { private $profiler; private $db; public function __construct() { $this->profiler = new PhpQuickProfiler(PhpQuickProfiler::getMicroTime()); } public function __destruct() { if($debugMode == true) $this->profiler->display($this->db); }}

Logging to the Console

Given the code shell above, PQP is configured and ready to be used. We can start referencing the helper functions, starting with logging. The console log is just a step above an echo statement in that it condenses and formats the output using print_r . This is useful for reviewers because it provides a way to view debugging information without blowing up the layout of the page. To output data to the console, just statically call the function:

Console::log($data);

The static function call accepts any data type and is available as long as the PhpQuickProfiler.php class is included. We chose to implement this with a static call so that the class does not have to be instantiated before use. The downside to a static call is that we store the log history in a global php variable. Should you wish to avoid globals, the Console.php class could always hold the log as a member variable given that it is instantiated. But as is, the class just acts as a read and write wrapper around a global PHP variable.

On top of logging variables, the console also has four additional functions.

Console::logError($exception); Console::logMemory(); Console::logMemory($variable, $name); Console::logSpeed();

Let’s start with logError() . Logging an error is useful for displaying information related to a PHP exception. In our code, we’ll use a catch block for handling errors so we can silence an exception. We do this because we want that error to be ignored and not affect what the user is doing. An example of this would be logging data that isn’t crucial. If that log fails, the users shouldn’t have to stop what they’re doing. Now, in development, it’s still nice to know those exceptions were thrown, so in the catch block a call to logError() can be made to display the information to the console like so:

try { // Execute non critical code } catch(Exception $e) { Console::logError($e, 'Unable to execute non critical code'); }

Additionally, the console can provide even more value by using some of the helper functions that PHP natively provides. For example, logging debug_backtrace() will print related information about the script at a given point in time. PHP also provides us with magic constants like __LINE__ , __FILE__ , __FUNCTION__ , __METHOD__ and __CLASS__ , which allows for printing of script data. Take a look at the screenshot below to see some example usage of this:

Watching Memory Usage

Object oriented PHP is a beautiful thing to behold, but there are definitely a few concerns to keep in mind when it comes to memory usage. These concerns tend to rear their heads when dealing with recursive output (i.e.: exporting to Excel), if there’s a leak in the creation of the objects or if objects aren’t being destroyed properly. All of this can lead to unexpected resource usage and fatal errors that serve to aggravate the end user.

The debugger aids with memory management by displaying the maximum amount of memory used by the script. A simple call to the built in memory_get_peak_usage() is where the data originates. The system setting for memory allowed (through ini_get() ) is also shown to see how much wiggle room there is. If an overview isn’t enough, you can drill down into your resource usage with a point in time memory call.

Console::logMemory(); Console::logMemory($variable, $name);

Calling logMemory() in your code without any parameters will output the current amount of memory that PHP is using when the function is called. This is perfect for watching a loop in your script to see if memory is building up during each iteration. Likewise, a variable and a name can be passed in to the function. Doing so will output the memory used by the variable to the console. Knowing that a script is hogging memory is wonderful, and knowing which variable is doing the hogging allows the problem to be fixed. Take a look at the screenshot below to see an example of string concatenation that is slowly eating up memory.

Runaway Includes

Similar to memory getting out of control, included files (especially on large complex projects) can multiply and take over your app before very quickly. Even worse, too many includes don’t throw the hard errors that memory usage does. Instead, the page just slows down and resources get eaten up on every request served. Avoiding this pitfall is pretty easy—just make sure the same file isn’t included multiple times, and catch any excessive includes of unnecessary files.

The PQP files tab shows the total files included with a count call on get_included_files and their total sizes are summed up. The names and sizes of the individual files are output to the console for easy scanning as well. The largest file included is noted on the left, which clearly points out if a large library is being used when it shouldn’t be. For example, on Wufoo we found out that we had a script always including htmLawed, a fairly decent sized file, when it wasn’t needed.

Also, keep in mind, autoloading classes or using require_once will usually alleviate any problems with file includes. That said, it never hurts to be aware of the situation, especially when using plugins, old code, or borrowed code.

Page Execution Time

Emphasis is always placed on database optimization when it comes to performance considerations (rightfully so), but that doesn’t mean PHP execution time should be ignored completely. The standard method for calculating load time is to find the difference between the time when the script starts and then again when the script finishes. This is where the integration of the debugger into your own project becomes tricky. Since the debugger is called on the destruction of the parent page, we know when the script is ending. But since every project is different, the start time can vary. The example code that you can download sets the start time in the construction of the parent object with a call to PQP ’s getMicroTime() . This will work in most cases, but if you have a lot of code going on before the parent is constructed, be sure to specifically set the start time when needed.

$this->profiler = new PhpQuickProfiler(PhpQuickProfiler::getMicroTime());

Given the page execution time, the next step would be to find meaning in the information. A quick glance will show if the time falls into an acceptable range. Assuming it doesn’t, how would we go about debugging the problem? Using the query section of the debugger, we can rule out query execution time (explained more in the next section). If queries aren’t the problem, then some portion of the script is. We can find this with the console.

Console::logSpeed();

A call to logSpeed() will tell us how long the script has taken up until that point in time. For example, imagine we have an object factory that constructs complex objects from a database. We also have an object engine that returns the object names from a database. When displaying 100 objects names to the screen, we would use either the factory or the engine. But using the engine would be much faster because we only need the names, and do not need the logic processing of object creation. If the developer did use the factory, logSpeed() would reveal the slowdown in the display loop, which ultimately identifies the problem.

On a similar note, we recently discovered that xCache improves our page execution time by over 60%. This was compared against other benchmarks by having all of our developers run quick tests against the code they were responsible for using PQP .

A Glance at Database Activity

Getting the debugger to report database information is the hardest part of integration with your own project. This step will only work if your database interaction is abstracted in some way. We talked about a simple database class awhile back, and have also released an example with the zip download (MySqlDatabase.php — you can follow the code in there to see a full implementation). The reason a class is so important is because information about each query must be stored as it happens, and a class allows the queries to each go through the same analysis without additional work by the programmer.

As a query is called, the database wrapper class stores the query and logs the time. The simplified code looks like this:

function query($sql) { $start = $this->getTime(); $rs = mysql_query($sql, $this->conn); $this->logQuery($sql, $start); return $rs; }function logQuery($sql, $start) { $query = array( 'sql' => $sql, 'time' => ($this->getTime() - $start)*1000 ); array_push($this->queries, $query); }

Using that concept, the class will have an array of all query information available to it. Then, the debugger can take that array and print out the information. The information that is currently stored is the query itself, and the time to execute. The time to execute is not exact — it is the microtime until PHP has a handle on the recordset, which will be slower than the query time if there is network latency with the database server. Viewing the queries at a glance is an easy and helpful way to look for queries that would affect more records than intended, that are being duplicated or those that open themselves up to SQL injection.

One of the most useful database features added to the debugger is the ability to EXPLAIN each query run. Each query is run again using the explain statement, and the results are presented below the query. This makes it easy to identify which queries are using their indexes properly.

Wrapping Up

The end goal of this debugging tool is to present a summary of useful information in an automated format. Usually, finding out about certain aspects of the code would require manual work and thought. And then if a problem is encountered, the debugger will hopefully make narrowing down the problem easier through the use of the extended Console functions. With that in mind, this tool is just an aid and is in no way meant to replace the standard, thorough procedures available to developers. The slow query log, PHP error log and full fledged debuggers and profilers are encouraged on top of this high level view to supplement the tools available to developers.