Okay, so your code is slow.  Why?  Is it your webservice call?  Or a new plugin you installed?  Is it your database calls?  File I/O?  You need a profiler.  A profiler gives you the ability to trace the performance of your code through every function call and create an overview of your system’s performance over a certain time period and helps you make intelligent decisions about where to look for problems.

Code profilers like xdebug and xhprof are essential tools to have for diagnosing performance bottlenecks.  I highly recommend you check them out.  If you have access to installing these extensions on your system, you can probably stop reading here.

But what if you’re in an environment where you can’t install an extension? Luckily, php has a built-in function called register_tick_function that gives you a way to hook in to every user function that’s called.  With this, you can write a profiler yourself.

Here’s some sample code to show you what I mean:

declare(ticks=1);
register_tick_function('do_profile');

a();

function do_profile() {
    $bt = debug_backtrace();
    if (count($bt) <= 1) {
         return;
    }
    $frame = $bt[1];
    unset($bt);
    $function = $frame['function'];
    echo __FUNCTION__ . ' :: ' . $function . PHP_EOL;
}

function a() {
    echo __FUNCTION__ . PHP_EOL;
    b();
}

function b() {
    echo __FUNCTION__ . PHP_EOL;
    c();
}

function c() {
    echo __FUNCTION__ . PHP_EOL;
}

And the output:

a
do_profile :: a
b
do_profile :: b
c
do_profile :: c
do_profile :: b
do_profile :: a

You’ll see in the output that the tick function is being called when the function is called, and again when the function is removed from the stack.

This can be incredibly useful if you attach a timer to it.

Note:  the declare(ticks=1); line is mandatory, it tells php to call your tick handler for every function.  You can change this to declare(ticks=10); to call the tick handler every tenth function if that fits your needs.

Here’s a very simple example of a working profiler. It’s practically the same code as above, but with a timer attached and a shutdown handler to show you the profile when the script is done:

declare(ticks=1);
register_tick_function('do_profile');
register_shutdown_function('show_profile');

$profile = array();
$last_time = microtime(true);

a();

function do_profile() {
    global $profile, $last_time;
    $bt = debug_backtrace();
    if (count($bt) <= 1) {
        return ;
    }
    $frame = $bt[1];
    unset($bt);
    $function = $frame['function'];
    if (!isset($profile[$function])) {
        $profile[$function] = array(
            'time'  => 0,
            'calls' => 0
        );
    }
    $profile[$function]['calls']++;
    $profile[$function]['time'] += (microtime(true) - $last_time);
    $last_time = microtime(true);
}

function show_profile() {
    global $profile;
    print_r($profile);
}

function a() {
    usleep(50 * 1000);
    b();
}

function b() {
    usleep(500 * 1000);
    c();
}

function c() {
    usleep(5000 * 1000);
}

And the output hopefully matches what you would expect:

Array
(
    [a] => Array
        (
            [time] => 0.0511748790741
            [calls] => 2
        )

    [b] => Array
        (
            [time] => 0.500598907471
            [calls] => 2
        )

    [c] => Array
        (
            [time] => 5.00052690506
            [calls] => 1
        )

)

The timing matches what we set in each function. The calls, though, is a bit off, since the tick handler can be called twice for each function. Just note that when you’re interpreting the results.

You can really amp this up to get some good info, though.  Check this out:

If you want to see how it’s done, or see how well it works, give the P3 Plugin for WordPress a look.

Caveats

The tick function is a user function.  This means that whenever php calls a user function it will call your tick function first, but since your  tick function is itself a user function, it will also have the tick function called for it.  It stops after one level of recursion.  Be sure to check for that in your code!

Ticks will not be called on php internal functions.  If your app is having problems due to I/O or an extension, you won’t be able to get the same granularity with a tick function as with an extension based profiler.

Bytecode optimizers will cause you problems.  Function calls will happen, but they won’t be sent through the tick function.  Not exactly sure why on this, but here’s what I’ve got so far:

• eaccelerator – optimization definitely causes problems
  • disable method 1 – set eaccelerator.optimizer to false
  • disable method 2 – if your app is in eaccelerator’s admin path, call eaccelerator_optimizer(false);
• xcache – the documentation says there is no optimizer until version 2.0, but experimentation shows some missing function calls, no solution yet
• zend optimizer+ –  some problems – you can turn this off by setting zend_optimizerplus.optimization_level to 0
• apc – optimization was removed in 3.0.13 – no problems found
• wincache – no problems found
• ioncube – no problems found
• zend guard loader – no problems found

There’s a warning that this function is not compatible with multi-threaded web servers and php < 5.3.  See the documentation on php.net for more details

Remember to optimize the tick function!  It will be called hundreds or thousands of times in your app, so milliseconds will add up!  If you have a slight mistake in your timing here, it will cause a big shift in your results.