Use register_tick_function to profile your code


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:

P3 Profiler Timeline

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.

About these ads

12 thoughts on “Use register_tick_function to profile your code

  1. How does this work:

    if (count($bt) {
    return;
    }
    $frame = $bt[1];

    Will $frame not always be empty? The function returns when $bt contains elements.

    Wolfgang

  2. Pingback: Kurt Paynes Blog: User register_tick_function, Ihren Code zu profilieren | PHP Boutique

  3. I planned to use same method for “event-driven” app.
    But due to significant overhead of unnecessary calls it seems like utopia.
    Anyway if anybody require to hook into existing functionality it could be a nice solution (remember that debug_backtrace() gives not only a called method name, line, etc, but also contain references on object which method is actually called).

    • Vladimir,

      I agree with you 100%. Debug backtrace is a pretty gnarly call to use and you have to be judicious how / when you use it.

      The later version of PHP are treating debug_backtrace a little more efficiently and allow you to chose what is included. I left the code above simple, but you could use something like this to get a very small backtrace:


      if ( version_compare( PHP_VERSION, '5.3.6' ) < 0 ) {
      $bt = debug_backtrace( false );
      } elseif ( version_compare( PHP_VERSION, '5.4.0' ) < 0 ) {
      $bt = debug_backtrace( 0 );
      } else {
      $bt = debug_backtrace( 0, 2 ); // Examine the last 2 frames
      }

      For more complex code with anonymous functions, you’ll need the original object. If you want to find out which files were passed to include/require, you’ll need the args.

    • Hi jaikdean,

      I kinda waffle on this one. Some how, $last_time needs to be initialized to the current time. Static variables cannot be initialized to a function call [source].

      So the new code would look like:


      static $last_time = 0;
      if (!$last_time) {
      $last_time = microtime(true);
      }

      It’s adding a conditional to the code instead of a global lookup. I’m not sure which is worse.

  4. Pingback: Tweet Heat - The hottest Tweets of the Month [Feb 2012] | Inspired Magazine

  5. Pingback: Tweet Heat – The hottest Tweets of the Month [Feb 2012] | CS5 Design

  6. Pingback: Write your own code profiler « House of Payne

  7. I did a small change that helped me get to the issue faster

                $profile[$function]['calls']++;
                $t = (microtime(true) - $last_time);
                $profile[$function]['time'] += $t;
    
                if($profile[$function]["longest"]["t"]<$t) {
                    $profile[$function]["longest"]["t"] = $t;
                    $profile[$function]["longest"]["stack"] = debug_backtrace();
                }
    

    this way i can know for sure where is the problem

    thanks! your code really helped me

Leave a Reply

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

WordPress.com Logo

You are commenting using your WordPress.com 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 )

Google+ photo

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

Connecting to %s