* * For the full copyright and license information, please view the LICENSE * file that was distributed with this source code. */ namespace Symfony\Component\HttpKernel\Debug; use Symfony\Component\Stopwatch\Stopwatch; use Symfony\Component\HttpKernel\Log\LoggerInterface; use Symfony\Component\HttpKernel\Profiler\Profile; use Symfony\Component\HttpKernel\Profiler\Profiler; use Symfony\Component\HttpKernel\HttpKernelInterface; use Symfony\Component\EventDispatcher\Event; use Symfony\Component\EventDispatcher\EventDispatcherInterface; use Symfony\Component\EventDispatcher\EventSubscriberInterface; use Symfony\Component\EventDispatcher\Debug\TraceableEventDispatcherInterface; /** * Collects some data about event listeners. * * This event dispatcher delegates the dispatching to another one. * * @author Fabien Potencier */ class TraceableEventDispatcher implements EventDispatcherInterface, TraceableEventDispatcherInterface { private $logger; private $called; private $stopwatch; private $profiler; private $dispatcher; private $wrappedListeners; private $firstCalledEvent; private $id; /** * Constructor. * * @param EventDispatcherInterface $dispatcher An EventDispatcherInterface instance * @param Stopwatch $stopwatch A Stopwatch instance * @param LoggerInterface $logger A LoggerInterface instance */ public function __construct(EventDispatcherInterface $dispatcher, Stopwatch $stopwatch, LoggerInterface $logger = null) { $this->dispatcher = $dispatcher; $this->stopwatch = $stopwatch; $this->logger = $logger; $this->called = array(); $this->wrappedListeners = array(); $this->firstCalledEvent = array(); } /** * Sets the profiler. * * @param Profiler|null $profiler A Profiler instance */ public function setProfiler(Profiler $profiler = null) { $this->profiler = $profiler; } /** * {@inheritDoc} */ public function addListener($eventName, $listener, $priority = 0) { $this->dispatcher->addListener($eventName, $listener, $priority); } /** * {@inheritdoc} */ public function addSubscriber(EventSubscriberInterface $subscriber) { $this->dispatcher->addSubscriber($subscriber); } /** * {@inheritdoc} */ public function removeListener($eventName, $listener) { return $this->dispatcher->removeListener($eventName, $listener); } /** * {@inheritdoc} */ public function removeSubscriber(EventSubscriberInterface $subscriber) { return $this->dispatcher->removeSubscriber($subscriber); } /** * {@inheritdoc} */ public function getListeners($eventName = null) { return $this->dispatcher->getListeners($eventName); } /** * {@inheritdoc} */ public function hasListeners($eventName = null) { return $this->dispatcher->hasListeners($eventName); } /** * {@inheritdoc} */ public function dispatch($eventName, Event $event = null) { if (null === $event) { $event = new Event(); } $this->id = spl_object_hash($event); $this->preDispatch($eventName, $event); $e = $this->stopwatch->start($eventName, 'section'); $this->firstCalledEvent[$eventName] = $this->stopwatch->start($eventName.'.loading', 'event_listener_loading'); $this->dispatcher->dispatch($eventName, $event); // reset the id as another event might have been dispatched during the dispatching of this event $this->id = spl_object_hash($event); unset($this->firstCalledEvent[$eventName]); $e->stop(); $this->postDispatch($eventName, $event); return $event; } /** * {@inheritDoc} */ public function getCalledListeners() { return $this->called; } /** * {@inheritDoc} */ public function getNotCalledListeners() { $notCalled = array(); foreach ($this->getListeners() as $name => $listeners) { foreach ($listeners as $listener) { $info = $this->getListenerInfo($listener, $name); if (!isset($this->called[$name.'.'.$info['pretty']])) { $notCalled[$name.'.'.$info['pretty']] = $info; } } } return $notCalled; } /** * Proxies all method calls to the original event dispatcher. * * @param string $method The method name * @param array $arguments The method arguments */ public function __call($method, $arguments) { return call_user_func_array(array($this->dispatcher, $method), $arguments); } /** * This is a private method and must not be used. * * This method is public because it is used in a closure. * Whenever Symfony will require PHP 5.4, this could be changed * to a proper private method. */ public function logSkippedListeners($eventName, Event $event, $listener) { if (null === $this->logger) { return; } $info = $this->getListenerInfo($listener, $eventName); $this->logger->debug(sprintf('Listener "%s" stopped propagation of the event "%s".', $info['pretty'], $eventName)); $skippedListeners = $this->getListeners($eventName); $skipped = false; foreach ($skippedListeners as $skippedListener) { $skippedListener = $this->unwrapListener($skippedListener, $eventName); if ($skipped) { $info = $this->getListenerInfo($skippedListener, $eventName); $this->logger->debug(sprintf('Listener "%s" was not called for event "%s".', $info['pretty'], $eventName)); } if ($skippedListener === $listener) { $skipped = true; } } } /** * This is a private method. * * This method is public because it is used in a closure. * Whenever Symfony will require PHP 5.4, this could be changed * to a proper private method. */ public function preListenerCall($eventName, $listener) { // is it the first called listener? if (isset($this->firstCalledEvent[$eventName])) { $this->firstCalledEvent[$eventName]->stop(); unset($this->firstCalledEvent[$eventName]); } $info = $this->getListenerInfo($listener, $eventName); if (null !== $this->logger) { $this->logger->debug(sprintf('Notified event "%s" to listener "%s".', $eventName, $info['pretty'])); } $this->called[$eventName.'.'.$info['pretty']] = $info; return $this->stopwatch->start(isset($info['class']) ? substr($info['class'], strrpos($info['class'], '\\') + 1) : $info['type'], 'event_listener'); } /** * Returns information about the listener * * @param object $listener The listener * @param string $eventName The event name * * @return array Informations about the listener */ private function getListenerInfo($listener, $eventName) { $listener = $this->unwrapListener($listener, $eventName); $info = array( 'event' => $eventName, ); if ($listener instanceof \Closure) { $info += array( 'type' => 'Closure', 'pretty' => 'closure' ); } elseif (is_string($listener)) { try { $r = new \ReflectionFunction($listener); $file = $r->getFileName(); $line = $r->getStartLine(); } catch (\ReflectionException $e) { $file = null; $line = null; } $info += array( 'type' => 'Function', 'function' => $listener, 'file' => $file, 'line' => $line, 'pretty' => $listener, ); } elseif (is_array($listener) || (is_object($listener) && is_callable($listener))) { if (!is_array($listener)) { $listener = array($listener, '__invoke'); } $class = is_object($listener[0]) ? get_class($listener[0]) : $listener[0]; try { $r = new \ReflectionMethod($class, $listener[1]); $file = $r->getFileName(); $line = $r->getStartLine(); } catch (\ReflectionException $e) { $file = null; $line = null; } $info += array( 'type' => 'Method', 'class' => $class, 'method' => $listener[1], 'file' => $file, 'line' => $line, 'pretty' => $class.'::'.$listener[1], ); } return $info; } /** * Updates the stopwatch data in the profile hierarchy. * * @param string $token Profile token * @param Boolean $updateChildren Whether to update the children altogether */ private function updateProfiles($token, $updateChildren) { if (!$this->profiler || !$profile = $this->profiler->loadProfile($token)) { return; } $this->saveInfoInProfile($profile, $updateChildren); } /** * Update the profiles with the timing and events information and saves them. * * @param Profile $profile The root profile * @param Boolean $updateChildren Whether to update the children altogether */ private function saveInfoInProfile(Profile $profile, $updateChildren) { $profile->getCollector('time')->setEvents($this->stopwatch->getSectionEvents($profile->getToken())); $profile->getCollector('events')->setCalledListeners($this->getCalledListeners()); $profile->getCollector('events')->setNotCalledListeners($this->getNotCalledListeners()); $this->profiler->saveProfile($profile); if ($updateChildren) { foreach ($profile->getChildren() as $child) { $this->saveInfoInProfile($child, true); } } } private function getListenerAsString($listener) { if (is_string($listener)) { return '[string] '.$listener; } elseif (is_array($listener)) { return '[array] '.(is_object($listener[0]) ? get_class($listener[0]) : $listener[0]).'::'.$listener[1]; } elseif (is_object($listener)) { return '[object] '.get_class($listener); } return '[?] '.var_export($listener, true); } private function preDispatch($eventName, Event $event) { // wrap all listeners before they are called $this->wrappedListeners[$this->id] = new \SplObjectStorage(); $listeners = $this->dispatcher->getListeners($eventName); foreach ($listeners as $listener) { $this->dispatcher->removeListener($eventName, $listener); $wrapped = $this->wrapListener($eventName, $listener); $this->wrappedListeners[$this->id][$wrapped] = $listener; $this->dispatcher->addListener($eventName, $wrapped); } switch ($eventName) { case 'kernel.request': $this->stopwatch->openSection(); break; case 'kernel.view': case 'kernel.response': // stop only if a controller has been executed try { $this->stopwatch->stop('controller'); } catch (\LogicException $e) { } break; case 'kernel.terminate': $token = $event->getResponse()->headers->get('X-Debug-Token'); $this->stopwatch->openSection($token); break; } } private function postDispatch($eventName, Event $event) { switch ($eventName) { case 'kernel.controller': $this->stopwatch->start('controller', 'section'); break; case 'kernel.response': $token = $event->getResponse()->headers->get('X-Debug-Token'); $this->stopwatch->stopSection($token); if (HttpKernelInterface::MASTER_REQUEST === $event->getRequestType()) { // The profiles can only be updated once they have been created // that is after the 'kernel.response' event of the main request $this->updateProfiles($token, true); } break; case 'kernel.terminate': $token = $event->getResponse()->headers->get('X-Debug-Token'); $this->stopwatch->stopSection($token); // The children profiles have been updated by the previous 'kernel.response' // event. Only the root profile need to be updated with the 'kernel.terminate' // timing informations. $this->updateProfiles($token, false); break; } foreach ($this->wrappedListeners[$this->id] as $wrapped) { $this->dispatcher->removeListener($eventName, $wrapped); $this->dispatcher->addListener($eventName, $this->wrappedListeners[$this->id][$wrapped]); } unset($this->wrappedListeners[$this->id]); } private function wrapListener($eventName, $listener) { $self = $this; return function (Event $event) use ($self, $eventName, $listener) { $e = $self->preListenerCall($eventName, $listener); call_user_func($listener, $event); $e->stop(); if ($event->isPropagationStopped()) { $self->logSkippedListeners($eventName, $event, $listener); } }; } private function unwrapListener($listener, $eventName) { // get the original listener if (is_object($listener) && isset($this->wrappedListeners[$this->id][$listener])) { return $this->wrappedListeners[$this->id][$listener]; } return $listener; } }