470 lines
15 KiB
PHP
470 lines
15 KiB
PHP
<?php
|
|
|
|
/*
|
|
* This file is part of the Symfony package.
|
|
*
|
|
* (c) Fabien Potencier <fabien@symfony.com>
|
|
*
|
|
* 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\KernelEvents;
|
|
use Psr\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 <fabien@symfony.com>
|
|
*/
|
|
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');
|
|
|
|
if (!$this->dispatcher->hasListeners($eventName)) {
|
|
$this->firstCalledEvent[$eventName]->stop();
|
|
}
|
|
|
|
$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
|
|
*
|
|
* @return mixed
|
|
*/
|
|
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);
|
|
|
|
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']) ? $info['class'] : $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);
|
|
|
|
$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)
|
|
{
|
|
try {
|
|
$collector = $profile->getCollector('memory');
|
|
$collector->updateMemoryUsage();
|
|
} catch (\InvalidArgumentException $e) {
|
|
}
|
|
|
|
try {
|
|
$collector = $profile->getCollector('time');
|
|
$collector->setEvents($this->stopwatch->getSectionEvents($profile->getToken()));
|
|
} catch (\InvalidArgumentException $e) {
|
|
}
|
|
|
|
try {
|
|
$collector = $profile->getCollector('events');
|
|
$collector->setCalledListeners($this->getCalledListeners());
|
|
$collector->setNotCalledListeners($this->getNotCalledListeners());
|
|
} catch (\InvalidArgumentException $e) {
|
|
}
|
|
|
|
$this->profiler->saveProfile($profile);
|
|
|
|
if ($updateChildren) {
|
|
foreach ($profile->getChildren() as $child) {
|
|
$this->saveInfoInProfile($child, 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 KernelEvents::REQUEST:
|
|
$this->stopwatch->openSection();
|
|
break;
|
|
case KernelEvents::VIEW:
|
|
case KernelEvents::RESPONSE:
|
|
// stop only if a controller has been executed
|
|
if ($this->stopwatch->isStarted('controller')) {
|
|
$this->stopwatch->stop('controller');
|
|
}
|
|
break;
|
|
case KernelEvents::TERMINATE:
|
|
$token = $event->getResponse()->headers->get('X-Debug-Token');
|
|
// There is a very special case when using builtin AppCache class as kernel wrapper, in the case
|
|
// of an ESI request leading to a `stale` response [B] inside a `fresh` cached response [A].
|
|
// In this case, `$token` contains the [B] debug token, but the open `stopwatch` section ID
|
|
// is equal to the [A] debug token. Trying to reopen section with the [B] token throws an exception
|
|
// which must be caught.
|
|
try {
|
|
$this->stopwatch->openSection($token);
|
|
} catch (\LogicException $e) {}
|
|
break;
|
|
}
|
|
}
|
|
|
|
private function postDispatch($eventName, Event $event)
|
|
{
|
|
switch ($eventName) {
|
|
case KernelEvents::CONTROLLER:
|
|
$this->stopwatch->start('controller', 'section');
|
|
break;
|
|
case KernelEvents::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 KernelEvents::TERMINATE:
|
|
$token = $event->getResponse()->headers->get('X-Debug-Token');
|
|
// In the special case described in the `preDispatch` method above, the `$token` section
|
|
// does not exist, then closing it throws an exception which must be caught.
|
|
try {
|
|
$this->stopwatch->stopSection($token);
|
|
} catch (\LogicException $e) {}
|
|
// 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)
|
|
{
|
|
// get the original listener
|
|
if (is_object($listener) && isset($this->wrappedListeners[$this->id][$listener])) {
|
|
return $this->wrappedListeners[$this->id][$listener];
|
|
}
|
|
|
|
return $listener;
|
|
}
|
|
}
|