debuggable

 
Contact Us
 

Spotting performance leaks in your application

Posted on 18/6/06 by Felix Geisendörfer

Today I was implementing a new and critical functionality into SpliceIt! that allows plugins to register global hooks like beforeFilter, afterFilter, etc. in order to make their own changes to the AppController (SpliceItAppController), even when they are not beeing requested. That way you can simply drop in a menu plugin, and your layout will automatically have the variable $menu set, even so the user didn't request any action from the menu plugin itself.

Anyway, when I implemented the first version I noticed a good performance loss right away, which I didn't like very much. So I had to figure out which part of my code was responsible for giving my processor such a hard time ; ). In order to do this I wrote a useful little singleton class that allows you to start, pause and resume multiple timers throughout your app in order to see what parts are eating up what performance.

Usage is very simple, after you've included the class with require/vendor/whatever you can use it like this:

Performance::startTimer('Sleep Walking');
sleep(1);
Performance::pauseTimer('Sleep Walking');
sleep(1);
Performance::resumeTimer('Sleep Walking');
sleep(1);

Performance::debugTimersPercantage();

// Outputs an array like this:
// Array
//  (
//       [sleep walking] => 1.99932789803 (52.04%)
//       [_total] => 3.84202480316 (100%)
//  )

Want to play around with it yourself? Here is the code:

class Performance
{
    var $_timers = array();
    var $time_start;
   
    /**
    * Returns a singleton instance of the Performance class
    *
    * @return unknown
    */

    function &getInstance()
    {
        static $instance = array();
        if (!$instance) {
            $instance[0] = &new Performance;
        }
            return $instance[0];
    }    
   
    /**
    * In the constructor we check if we already know the time our Application started (by checking for
    * the variable $TIME_START like cakephp set's it. Or we use the current time as our starttime.
    *
    * @return Performance
    */

    function Performance()
    {
        global $TIME_START;
   
        if (!empty($TIME_START))
            $this->time_start = $TIME_START;
        else
            $this->time_start = $this->getMicrotime();
    }
   
    /**
    * Starts a new timer $key. If such a timer has already been started it's going to be reset to 0.
    *
    * @param string $key
    */

    function startTimer($key)
    {
        $_this =& Performance::getInstance();
   
        $key = strtolower($key);     
        $_this->_timers[$key] = $_this->getMicrotime();
    }
   
    /**
    * Pauses the timer $key. You can resume it using Performance::resumeTimer()
    *
    * @param string $key
    */

    function pauseTimer($key)
    {
        $_this =& Performance::getInstance();
       
        $key = strtolower($key);
        $_this->_timers[$key] = array($_this->getTimer($key));
    } 
   
    /**
    * Resumes the timer $key if it had been paused before. If not nothing happens, and if such a timer
    * doesn't exists it get's created via Performance::startTimer() automatically.
    *
    * @param string $key
    */

    function resumeTimer($key)
    {
        $now = Performance::getMicrotime();
        $_this =& Performance::getInstance();
       
        $key = strtolower($key);
       
        if (!$_this->isKeySet($key))
            return $_this->startTimer($key);
       
        $timerStart = $_this->_timers[$key];     
       
        if (is_array($timerStart))
            $_this->_timers[$key] = $now-array_pop($timerStart);
    }
   
    /**
    * Removes the timer $key from the list of timers
    *
    * @param unknown_type $key
    */

    function removeTimer($key)
    {
        $_this =& Performance::getInstance();
       
        $key = strtolower($key);     
        if (array_key_exists($key, $_this->_timers) === true)
            unset($_this->_timers[$key]);
    } 
   
    /**
    * Get's the current amount of time ellapsed for timer $timer.
    *
    * @param string $key
    * @return float
    */

    function getTimer($key, $now = null)
    {
        if (empty($now))
            $now = Performance::getMicrotime();
   
        $_this =& Performance::getInstance();
   
        $key = strtolower($key);    
        $timerStart = $_this->_timers[$key];
   
   
        if (is_array($timerStart))
            return array_pop($timerStart);
        else
            return $now - $timerStart;
    }
   
    /**
    * Get's a list of all registered timers and their current amount of ellapsed time.
    *
    * @return array
    */

    function getTimers()
    {
        $now = Performance::getMicrotime();
   
        $_this =& Performance::getInstance();   
   
        $timers = array();
   
        foreach ($_this->_timers as $key => $timer)
        {
            $timers[$key] = $_this->getTimer($key, $now);
        }
   
        $timers['_total'] = $now-$_this->time_start;
   
        return $timers;
    }
   
    /**
    * Returns the percantage that the timer $key has taken up in time compared
    * to the total execution time of the script (see the constructor to make sure
    * this works).
    *
    * @param string $key
    * @param float $now
    * @param float $timer
    * @return float
    */

    function getTimerPercantage($key, $now = null, $timer = null)
    {
        if (empty($now))
            $now = Performance::getMicrotime();
   
        $_this =& Performance::getInstance();
        if (empty($timer))
            $timer = $_this->getTimer($key, $now);
       
        return $timer.' ('.round((($timer)/($now-$_this->time_start)*100), 2).'%)';
    }
   
    /**
    * Get's a list of all timers together with the time percantage they have used up.
    * The total may add up to over 100% if some of the timers have been running at the
    * same time.
    *
    * @return array
    */

    function getTimersPercantage()
    {
        $now = Performance::getMicrotime();
        $_this =& Performance::getInstance();
       
        $timers = $_this->getTimers();
        $percantageTimers = array();
       
        foreach ($timers as $key => $timer)
        {
            $percantageTimers[$key] = $_this->getTimerPercantage($key, $now, $timer);
        }      
       
        return $percantageTimers;       
    }
   
    /**
    * Checks if the timer $key exists or not.
    *
    * @param unknown_type $key
    * @return unknown
    */

    function isKeySet($key) {
        $_this =& Performance::getInstance();
       
        $key = strtolower($key);
        return array_key_exists($key, $_this->_timers);
    } 
   
    /**
    * A convenience function for debug(Performance::getTimer($key));
    *
    * @param string $key
    */

    function debugTimer($key)
    {
        debug(Performance::getTimer($key));
    }
   
    /**
    * A convenience function for debug(Performance::getTimers($key));
    *
    * @param string $key
    */
 
    function debugTimers()
    {
        debug(Performance::getTimers());
    }
   
    /**
    * A convenience function for debug(Performance::getTimerPercantage($key));
    *
    * @param string $key
    */
   
    function debugTimerPercantage($key)
    {
        debug(Performance::getTimerPercantage($key));
    }
   
    /**
    * A convenience function for debug(Performance::getTimersPercantage($key));
    *
    * @param string $key
    */
   
    function debugTimersPercantage()
    {
        debug(Performance::getTimersPercantage());
    } 
   
    /**
    * Returns the microtime in seconds as a float. I know php5 / cakephp already have this function,
    * but I wanted a maximum of reusability for this class.
    *
    * @return float
    */

    function getMicrotime()
    {
        return array_sum(explode(chr(32), microtime()));
    } 
}

The license for it is MIT. Another thing I'd like to point out, is the fact that some of the code was inspired/derived from CakePHP's ClassRegistry class which you can find inside cake/libs/class_registry.php.

If you like the class or find a bug, any feedback is welcome ; ).

--Felix Geisendörfer aka the_undefined

 
&nsbp;

You can skip to the end and add a comment.

RosSoft  said on Jun 18, 2006:

It gives me an error, I think that line 163 should be $_this instead of $this

return $timer.' ('.round((($timer)/($now-$_this->time_start)*100), 2).'%)';

RosSoft  said on Jun 18, 2006:

BTW, that's an useful class, thanks

Felix Geisendörfer said on Jun 18, 2006:

Hey RosSoft, thanks for pointing that out, I corrected it in the code above. Oh and I'm glad you find the class useful ; ).

David Rodger  said on Jun 22, 2006:

Why not this...?

function Performance()
{

if (!empty($this->time_start)) {

$this->time_start = $this->getMicrotime();

}

}

Since the Performance object is a singleton, the class variable $time_start ought to persist as long as the object.

Felix Geisendörfer said on Jun 22, 2006:

David Rodger: As I designed this class, $time_start is supposed to contain the time the application has started and not the time the class has first been instanced. Now when the $TIME_START variable isn't available (it is set by cakephp), then I fall back to the earliest time I can be sure of, that the app has already been running (the time the class has been created/accessed for the first time for that matter).

I want it to be like this because if you have only one timer and want to see if the functionality it tracks is reasonably fast, you can't rely on the absolute time the function takes, because you have nothing to compare it to. So for that reason I compare my functions with the total execution time of my app in order to see if they are efficent or not as this will be a reasonable indicator with all hardware.

Hope that clarifies it ; ).

Tarique Sani said on Jun 25, 2006:

Why not simply use selective profiling of Xdebug?

Felix Geisendörfer said on Jun 25, 2006:

Because I've never heard of xdebug before and sometimes you can't install extensions on the server you have to work with. That's about it, feel free to use whatever suits your needs best.

This post is too old. We do not allow comments here anymore in order to fight spam. If you have real feedback or questions for the post, please contact us.