Spotting performance leaks in your application

Posted by Felix Geisendörfer, on Jun 18, 2006 - in PHP & CakePHP » Performance, Optimization & Caching

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:

php
  1. Performance::startTimer('Sleep Walking');
  2. sleep(1);
  3. Performance::pauseTimer('Sleep Walking');
  4. sleep(1);
  5. Performance::resumeTimer('Sleep Walking');
  6. sleep(1);
  7.  
  8. Performance::debugTimersPercantage();
  9.  
  10. // Outputs an array like this:
  11. // Array
  12. //  (
  13. //       [sleep walking] => 1.99932789803 (52.04%)
  14. //       [_total] => 3.84202480316 (100%)
  15. //  )

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

php
  1. class Performance
  2. {
  3.     var $_timers = array();
  4.     var $time_start;
  5.    
  6.     /**
  7.     * Returns a singleton instance of the Performance class
  8.     *
  9.     * @return unknown
  10.     */
  11.     function &getInstance()
  12.     {
  13.         static $instance = array();
  14.         if (!$instance) {
  15.             $instance[0] = &new Performance;
  16.         }
  17.             return $instance[0];
  18.     }    
  19.    
  20.     /**
  21.     * In the constructor we check if we already know the time our Application started (by checking for
  22.     * the variable $TIME_START like cakephp set's it. Or we use the current time as our starttime.
  23.     *
  24.     * @return Performance
  25.     */
  26.     function Performance()
  27.     {
  28.         global $TIME_START;
  29.    
  30.         if (!empty($TIME_START))
  31.             $this->time_start = $TIME_START;
  32.         else
  33.             $this->time_start = $this->getMicrotime();
  34.     }
  35.    
  36.     /**
  37.     * Starts a new timer $key. If such a timer has already been started it's going to be reset to 0.
  38.     *
  39.     * @param string $key
  40.     */
  41.     function startTimer($key)
  42.     {
  43.         $_this =& Performance::getInstance();
  44.    
  45.         $key = strtolower($key);     
  46.         $_this->_timers[$key] = $_this->getMicrotime();
  47.     }
  48.    
  49.     /**
  50.     * Pauses the timer $key. You can resume it using Performance::resumeTimer()
  51.     *
  52.     * @param string $key
  53.     */
  54.     function pauseTimer($key)
  55.     {
  56.         $_this =& Performance::getInstance();
  57.        
  58.         $key = strtolower($key);
  59.         $_this->_timers[$key] = array($_this->getTimer($key));
  60.     } 
  61.    
  62.     /**
  63.     * Resumes the timer $key if it had been paused before. If not nothing happens, and if such a timer
  64.     * doesn't exists it get's created via Performance::startTimer() automatically.
  65.     *
  66.     * @param string $key
  67.     */
  68.     function resumeTimer($key)
  69.     {
  70.         $now = Performance::getMicrotime();
  71.         $_this =& Performance::getInstance();
  72.        
  73.         $key = strtolower($key);
  74.        
  75.         if (!$_this->isKeySet($key))
  76.             return $_this->startTimer($key);
  77.        
  78.         $timerStart = $_this->_timers[$key];     
  79.        
  80.         if (is_array($timerStart))
  81.             $_this->_timers[$key] = $now-array_pop($timerStart);
  82.     }
  83.    
  84.     /**
  85.     * Removes the timer $key from the list of timers
  86.     *
  87.     * @param unknown_type $key
  88.     */
  89.     function removeTimer($key)
  90.     {
  91.         $_this =& Performance::getInstance();
  92.        
  93.         $key = strtolower($key);     
  94.         if (array_key_exists($key, $_this->_timers) === true)
  95.             unset($_this->_timers[$key]);
  96.     } 
  97.    
  98.     /**
  99.     * Get's the current amount of time ellapsed for timer $timer.
  100.     *
  101.     * @param string $key
  102.     * @return float
  103.     */
  104.     function getTimer($key, $now = null)
  105.     {
  106.         if (empty($now))
  107.             $now = Performance::getMicrotime();
  108.    
  109.         $_this =& Performance::getInstance();
  110.    
  111.         $key = strtolower($key);    
  112.         $timerStart = $_this->_timers[$key];
  113.    
  114.    
  115.         if (is_array($timerStart))
  116.             return array_pop($timerStart);
  117.         else
  118.             return $now - $timerStart;
  119.     }
  120.    
  121.     /**
  122.     * Get's a list of all registered timers and their current amount of ellapsed time.
  123.     *
  124.     * @return array
  125.     */
  126.     function getTimers()
  127.     {
  128.         $now = Performance::getMicrotime();
  129.    
  130.         $_this =& Performance::getInstance();   
  131.    
  132.         $timers = array();
  133.    
  134.         foreach ($_this->_timers as $key => $timer)
  135.         {
  136.             $timers[$key] = $_this->getTimer($key, $now);
  137.         }
  138.    
  139.         $timers['_total'] = $now-$_this->time_start;
  140.    
  141.         return $timers;
  142.     }
  143.    
  144.     /**
  145.     * Returns the percantage that the timer $key has taken up in time compared
  146.     * to the total execution time of the script (see the constructor to make sure
  147.     * this works).
  148.     *
  149.     * @param string $key
  150.     * @param float $now
  151.     * @param float $timer
  152.     * @return float
  153.     */
  154.     function getTimerPercantage($key, $now = null, $timer = null)
  155.     {
  156.         if (empty($now))
  157.             $now = Performance::getMicrotime();
  158.    
  159.         $_this =& Performance::getInstance();
  160.         if (empty($timer))
  161.             $timer = $_this->getTimer($key, $now);
  162.        
  163.         return $timer.' ('.round((($timer)/($now-$_this->time_start)*100), 2).'%)';
  164.     }
  165.    
  166.     /**
  167.     * Get's a list of all timers together with the time percantage they have used up.
  168.     * The total may add up to over 100% if some of the timers have been running at the
  169.     * same time.
  170.     *
  171.     * @return array
  172.     */
  173.     function getTimersPercantage()
  174.     {
  175.         $now = Performance::getMicrotime();
  176.         $_this =& Performance::getInstance();
  177.        
  178.         $timers = $_this->getTimers();
  179.         $percantageTimers = array();
  180.        
  181.         foreach ($timers as $key => $timer)
  182.         {
  183.             $percantageTimers[$key] = $_this->getTimerPercantage($key, $now, $timer);
  184.         }      
  185.        
  186.         return $percantageTimers;       
  187.     }
  188.    
  189.     /**
  190.     * Checks if the timer $key exists or not.
  191.     *
  192.     * @param unknown_type $key
  193.     * @return unknown
  194.     */
  195.     function isKeySet($key) {
  196.         $_this =& Performance::getInstance();
  197.        
  198.         $key = strtolower($key);
  199.         return array_key_exists($key, $_this->_timers);
  200.     } 
  201.    
  202.     /**
  203.     * A convenience function for debug(Performance::getTimer($key));
  204.     *
  205.     * @param string $key
  206.     */
  207.     function debugTimer($key)
  208.     {
  209.         debug(Performance::getTimer($key));
  210.     }
  211.    
  212.     /**
  213.     * A convenience function for debug(Performance::getTimers($key));
  214.     *
  215.     * @param string $key
  216.     */ 
  217.     function debugTimers()
  218.     {
  219.         debug(Performance::getTimers());
  220.     }
  221.    
  222.     /**
  223.     * A convenience function for debug(Performance::getTimerPercantage($key));
  224.     *
  225.     * @param string $key
  226.     */   
  227.     function debugTimerPercantage($key)
  228.     {
  229.         debug(Performance::getTimerPercantage($key));
  230.     }
  231.    
  232.     /**
  233.     * A convenience function for debug(Performance::getTimersPercantage($key));
  234.     *
  235.     * @param string $key
  236.     */   
  237.     function debugTimersPercantage()
  238.     {
  239.         debug(Performance::getTimersPercantage());
  240.     } 
  241.    
  242.     /**
  243.     * Returns the microtime in seconds as a float. I know php5 / cakephp already have this function,
  244.     * but I wanted a maximum of reusability for this class.
  245.     *
  246.     * @return float
  247.     */
  248.     function getMicrotime()
  249.     {
  250.         return array_sum(explode(chr(32), microtime()));
  251.     } 
  252. }

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