Magento 1.9.3.4 check events fired by custom modules and time it takes to perform

Question

In my magento site there are 40 + custom extensions. Page speed extremly slow did everything to optimize the frontend but no progress so i want to track all the events fire by extensions.

I tried to log the Events by writing Mage::log($name,'event.log',null) in Mage.php file which logs all the magento's events not the events fired by custom module.

How can i check which events are being fired by custom module and How much time it takes to load.

if i want to optimize it code level then what else do i need to check?

Any help would be appreciated.

Answer 1

IMPORTANT

Below sample code is to modify the core magento code, which is NOT RECOMMENDED in production mode. Please REVERT the code whenever you are done with the investigation

Modify app/code/core/Model/Mage.php dispatchEvent() method as below:

This will log all custom events triggered by magento into a log file 'var/log/custom_events.log'

public function dispatchEvent($eventName, $args)
{
            $eventName = strtolower($eventName);
            foreach ($this->_events as $area=>$events) {
                if (!isset($events[$eventName])) {
                    $eventConfig = $this->getConfig()->getEventConfig($area, $eventName);
                    if (!$eventConfig) {
                        $this->_events[$area][$eventName] = false;
                        continue;
                    }
                    $observers = array();
                    foreach ($eventConfig->observers->children() as $obsName=>$obsConfig) {
                        $observers[$obsName] = array(
                            'type'  => (string)$obsConfig->type,
                            'model' => $obsConfig->class ? (string)$obsConfig->class : $obsConfig->getClassName(),
                            'method'=> (string)$obsConfig->method,
                            'args'  => (array)$obsConfig->args,
                        );
                    }
                    $events[$eventName]['observers'] = $observers;
                    $this->_events[$area][$eventName]['observers'] = $observers;
                }
                if (false===$events[$eventName]) {
                    continue;
                } else {
                    $event = new Varien_Event($args);
                    $event->setName($eventName);
                    $observer = new Varien_Event_Observer();
                }

                foreach ($events[$eventName]['observers'] as $obsName=>$obs) {
                    $observer->setData(array('event'=>$event));
                    Varien_Profiler::start('OBSERVER: '.$obsName);
                    switch ($obs['type']) {
                        case 'disabled':
                            break;
                        case 'object':
                        case 'model':
                            $method = $obs['method'];
                            $observer->addData($args);
                            $object = Mage::getModel($obs['model']);
                            //Edited Here
                            $startTime = microtime(true);
                            $this->_callObserverMethod($object, $method, $observer);
                            ##########################
                            ######## Edit Here #######
                            ##########################
                            $executionTime = microtime(true) - $startTime;
                            $this->logCustomEvents($observer, $method, $executionTime);
                            break;
                        default:
                            $method = $obs['method'];
                            $observer->addData($args);
                            $object = Mage::getSingleton($obs['model']);
                            //Edited Here
                            $startTime = microtime(true);
                            $this->_callObserverMethod($object, $method, $observer);
                            ##########################
                            ######## Edit Here #######
                            ##########################
                            $executionTime = microtime(true) - $startTime;
                            $this->logCustomEvents($object, $method, $executionTime);
                            break;
                    }
                    Varien_Profiler::stop('OBSERVER: '.$obsName);
                }
            }
            return $this;
        }


        //New method to log
        protected function logCustomEvents($object, $event, $executionTime) 
        {
            $className = get_class($object);
            if (!strstr($className, 'Mage_')) {
                $logData = "{$className}::{$event} Executed For {$executionTime}";
                Mage::log($logData, null, 'custom_event.log');
            }
        }

REVERT THE CODE ONCE YOU ARE DONE

Also inorder to trace more performance related issues, you can install tools like newrelic which will give you pretty good idea about the slow areas of your website.

Answer 2

I'd recommend you to profile all page types (CMS, product list, product view, etc...) to retrieve information about all possible bottlenecks. For that, I've always used Aoe_Profiler extension (Fabrizio Branca), which provides a very nice & useful graphical representation for all code executed during a page request

You can read more info here: http://fbrnc.net/blog/2012/08/magento-profiler