diff --git a/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php b/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php index 823bce0082..c2116ea663 100644 --- a/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php +++ b/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php @@ -49,14 +49,22 @@ class TraceableEventDispatcher extends ContainerAwareEventDispatcher implements public function dispatch($eventName, Event $event = null) { - if ('kernel.request' === $eventName) { - $this->stopwatch->startSection(); - } elseif ('kernel.view' === $eventName || 'kernel.response' === $eventName) { - // stop only if a controller has been executed - try { - $this->stopwatch->stop('controller'); - } catch (\LogicException $e) { - } + 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; } $e1 = $this->stopwatch->start($eventName, 'section'); @@ -65,14 +73,19 @@ class TraceableEventDispatcher extends ContainerAwareEventDispatcher implements $e1->stop(); - if ('kernel.controller' === $eventName) { - $this->stopwatch->start('controller', 'section'); - } elseif ('kernel.response' === $eventName) { - $token = $event->getResponse()->headers->get('X-Debug-Token'); - - $this->stopwatch->stopSection($token); - - $this->updateProfile($token); + 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); + $this->updateProfile($token); + break; + case 'kernel.terminate': + $this->stopwatch->stopSection($token); + $this->updateProfile($token); + break; } } @@ -236,6 +249,11 @@ class TraceableEventDispatcher extends ContainerAwareEventDispatcher implements return $info; } + /** + * Updates the profile data. + * + * @param string $token Profile token + */ private function updateProfile($token) { if (!$this->getContainer()->has('profiler')) { @@ -247,7 +265,7 @@ class TraceableEventDispatcher extends ContainerAwareEventDispatcher implements return; } - $profile->getCollector('time')->setEvents($this->stopwatch->getSectionEvents($profile->getToken())); + $profile->getCollector('time')->setEvents($this->stopwatch->getSectionEvents($token)); $profiler->saveProfile($profile); // children diff --git a/src/Symfony/Bundle/WebProfilerBundle/Resources/views/Collector/time.html.twig b/src/Symfony/Bundle/WebProfilerBundle/Resources/views/Collector/time.html.twig index 9515272f7b..6a97c900b5 100644 --- a/src/Symfony/Bundle/WebProfilerBundle/Resources/views/Collector/time.html.twig +++ b/src/Symfony/Bundle/WebProfilerBundle/Resources/views/Collector/time.html.twig @@ -64,14 +64,14 @@

Main Request - - {{ collector.events.section.totaltime }} ms + - {{ collector.events.__section__.totaltime }} ms {% if profile.parent %} - - parent + - parent {% endif %}

- {% set max = collector.events.section.endtime %} + {% set max = collector.events.__section__.endtime %} {{ _self.display_timeline('timeline_' ~ token, collector.events, threshold, colors, width) }} @@ -79,8 +79,8 @@ {% for child in profile.children %} {% set events = child.getcollector('time').events %}

- Sub-request "{{ child.getcollector('request').requestattributes.get('_controller') }}" - - {{ events.section.totaltime }} ms + Sub-request "{{ child.getcollector('request').requestattributes.get('_controller') }}" + - {{ events.__section__.totaltime }} ms

{{ _self.display_timeline('timeline_' ~ child.token, events, threshold, colors, width) }} @@ -114,7 +114,7 @@ request.events.forEach(function(event) { event.periods.forEach(function(period) { - if ('section.child' === event.name) { + if ('__section__.child' === event.name) { ctx.fillStyle = colors.child_sections; ctx.fillRect(x + period.begin * ratio, 0, (period.end - period.begin) * ratio, height); } else if ('section' === event.category) { @@ -132,7 +132,7 @@ }); mainEvents = request.events.filter(function(event) { - return 'section.child' !== event.name; + return '__section__.child' !== event.name; }); mainEvents.forEach(function(event) { @@ -237,14 +237,14 @@ } var requests_data = { - "max": {{ collector.events.section.endtime }}, + "max": {{ collector.events.__section__.endtime }}, "requests": [ -{{ _self.dump_request_data(token, profile, collector.events, collector.events.section.origin) }} +{{ _self.dump_request_data(token, profile, collector.events, collector.events.__section__.origin) }} {% if profile.children|length %} , {% for child in profile.children %} -{{ _self.dump_request_data(child.token, child, child.getcollector('time').events, collector.events.section.origin) }}{{ loop.last ? '' : ',' }} +{{ _self.dump_request_data(child.token, child, child.getcollector('time').events, collector.events.__section__.origin) }}{{ loop.last ? '' : ',' }} {% endfor %} {% endif %} ] @@ -257,7 +257,7 @@ {% macro dump_request_data(token, profile, events, origin) %} { "id": "{{ token }}", - "left": {{ events.section.origin - origin }}, + "left": {{ events.__section__.origin - origin }}, "events": [ {{ _self.dump_events(events) }} ] @@ -266,7 +266,7 @@ {% macro dump_events(events) %} {% for name, event in events %} -{% if 'section' != name %} +{% if '__section__' != name %} { "name": "{{ name }}", "category": "{{ event.category }}", @@ -286,7 +286,7 @@ {% macro display_timeline(id, events, threshold, colors, width) %} {% set height = 0 %} - {% for name, event in events if 'section' != name and event.totaltime >= threshold %} + {% for name, event in events if '__section__' != name and event.totaltime >= threshold %} {% set height = height + 38 %} {% endfor %} diff --git a/src/Symfony/Component/HttpKernel/DataCollector/TimeDataCollector.php b/src/Symfony/Component/HttpKernel/DataCollector/TimeDataCollector.php index bdeb84cc3a..a91e91c78c 100644 --- a/src/Symfony/Component/HttpKernel/DataCollector/TimeDataCollector.php +++ b/src/Symfony/Component/HttpKernel/DataCollector/TimeDataCollector.php @@ -68,14 +68,13 @@ class TimeDataCollector extends DataCollector /** * Gets the request elapsed time. * - * @return integer The elapsed time + * @return float The elapsed time */ public function getTotalTime() { - $values = array_values($this->data['events']); - $lastEvent = $values[count($values) - 1]; + $lastEvent = $this->data['events']['__section__']; - return $lastEvent->getOrigin() + $lastEvent->getEndTime() - $this->data['start_time']; + return $lastEvent->getOrigin() + $lastEvent->getTotalTime() - $this->data['start_time']; } /** @@ -83,11 +82,11 @@ class TimeDataCollector extends DataCollector * * This is the time spent until the beginning of the request handling. * - * @return integer The elapsed time + * @return float The elapsed time */ public function getInitTime() { - return $this->data['events']['section']->getOrigin() - $this->getStartTime(); + return $this->data['events']['__section__']->getOrigin() - $this->getStartTime(); } /** diff --git a/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php b/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php index f964d4228b..b4de49ba99 100644 --- a/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php +++ b/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php @@ -18,25 +18,32 @@ namespace Symfony\Component\HttpKernel\Debug; */ class Stopwatch { - private $waiting; private $sections; - private $events; - private $origin; + private $activeSections; + + public function __construct() + { + $this->sections = $this->activeSections = array('__root__' => new Section('__root__')); + } /** - * Starts a new section. + * Creates a new section or re-opens an existing section. + * + * @param string|null $id The id of the session to re-open, null to create a new one + * + * @throws \LogicException When the section to re-open is not reachable */ - public function startSection() + public function openSection($id = null) { - if ($this->events) { - $this->start('section.child', 'section'); - $this->waiting[] = array($this->events, $this->origin); - $this->events = array(); + $current = end($this->activeSections); + + if (null !== $id && null === $current->get($id)) { + throw new \LogicException(sprintf('The section "%s" has been started at an other level and can not be opened.', $id)); } - $this->origin = microtime(true) * 1000; - - $this->start('section'); + $this->start('__section__.child', 'section'); + $this->activeSections[] = $current->open($id); + $this->start('__section__'); } /** @@ -50,19 +57,14 @@ class Stopwatch */ public function stopSection($id) { - $this->stop('section'); + $this->stop('__section__'); - if (null !== $id) { - $this->sections[$id] = $this->events; + if (1 == count($this->activeSections)) { + throw new \LogicException('There is no started section to stop.'); } - if ($this->waiting) { - list($this->events, $this->origin) = array_pop($this->waiting); - $this->stop('section.child'); - } else { - $this->origin = null; - $this->events = array(); - } + $this->sections[$id] = array_pop($this->activeSections)->setId($id); + $this->stop('__section__.child'); } /** @@ -74,6 +76,129 @@ class Stopwatch * @return StopwatchEvent A StopwatchEvent instance */ public function start($name, $category = null) + { + return end($this->activeSections)->startEvent($name, $category); + } + + /** + * Stops an event. + * + * @param string $name The event name + * + * @return StopwatchEvent A StopwatchEvent instance + */ + public function stop($name) + { + return end($this->activeSections)->stopEvent($name); + } + + /** + * Stops then restarts an event. + * + * @param string $name The event name + * + * @return StopwatchEvent A StopwatchEvent instance + */ + public function lap($name) + { + return end($this->activeSections)->stopEvent($name)->start(); + } + + /** + * Gets all events for a given section. + * + * @param string $id A section identifier + * + * @return StopwatchEvent[] An array of StopwatchEvent instances + */ + public function getSectionEvents($id) + { + return isset($this->sections[$id]) ? $this->sections[$id]->getEvents() : array(); + } +} + +class Section +{ + private $events = array(); + private $origin; + private $id; + private $children = array(); + + /** + * Constructor. + * + * @param float|null $origin Set the origin of the events in this section, use null to set their origin to their start time + */ + public function __construct($origin = null) + { + $this->origin = is_numeric($origin) ? $origin : null; + } + + /** + * Returns the child section. + * + * @param string $id The child section identifier + * + * @return Section|null The child section or null when none found + */ + public function get($id) + { + foreach ($this->children as $child) { + if ($id === $child->getId()) { + return $child; + } + } + + return null; + } + + /** + * Creates or re-opens a child section. + * + * @param string|null $id null to create a new section, the identifier to re-open an existing one. + * + * @return Section A child section + */ + public function open($id) + { + if (null === $session = $this->get($id)) { + $session = $this->children[] = new self(microtime(true) * 1000); + } + + return $session; + } + + /** + * @return string The identifier of the section + */ + public function getId() + { + return $this->id; + } + + /** + * Sets the session identifier. + * + * @param string $id The session identifier + * + * @return Section The current section + */ + public function setId($id) + { + $this->id = $id; + + return $this; + } + + /** + * Starts an event. + * + * @param string $name The event name + * @param string $category The event category + * + * @return StopwatchEvent The event + */ + public function startEvent($name, $category) { if (!isset($this->events[$name])) { $this->events[$name] = new StopwatchEvent($this->origin ?: microtime(true) * 1000, $category); @@ -87,9 +212,11 @@ class Stopwatch * * @param string $name The event name * - * @return StopwatchEvent A StopwatchEvent instance + * @return StopwatchEvent The event + * + * @throws \LogicException When the event has not been started */ - public function stop($name) + public function stopEvent($name) { if (!isset($this->events[$name])) { throw new \LogicException(sprintf('Event "%s" is not started.', $name)); @@ -99,11 +226,13 @@ class Stopwatch } /** - * Stops then restart an event. + * Stops then restarts an event. * * @param string $name The event name * - * @return StopwatchEvent A StopwatchEvent instance + * @return StopwatchEvent The event + * + * @throws \LogicException When the event has not been started */ public function lap($name) { @@ -111,14 +240,12 @@ class Stopwatch } /** - * Gets all events for a given section. - * - * @param string $id A section identifier + * Returns the events from this section. * * @return StopwatchEvent[] An array of StopwatchEvent instances */ - public function getSectionEvents($id) + public function getEvents() { - return isset($this->sections[$id]) ? $this->sections[$id] : array(); + return $this->events; } -} +} \ No newline at end of file diff --git a/src/Symfony/Component/HttpKernel/Debug/StopwatchEvent.php b/src/Symfony/Component/HttpKernel/Debug/StopwatchEvent.php index f606f1bcd1..70b6a5e74f 100644 --- a/src/Symfony/Component/HttpKernel/Debug/StopwatchEvent.php +++ b/src/Symfony/Component/HttpKernel/Debug/StopwatchEvent.php @@ -26,7 +26,7 @@ class StopwatchEvent /** * Constructor. * - * @param integer $origin The origin time in milliseconds + * @param float $origin The origin time in milliseconds * @param string $category The event category * * @throws \InvalidArgumentException When the raw time is not valid @@ -62,7 +62,7 @@ class StopwatchEvent /** * Starts a new event period. * - * @return StopwatchEvent The event. + * @return StopwatchEvent The event */ public function start() { @@ -74,7 +74,7 @@ class StopwatchEvent /** * Stops the last started event period. * - * @return StopwatchEvent The event. + * @return StopwatchEvent The event */ public function stop() { @@ -90,7 +90,7 @@ class StopwatchEvent /** * Stops the current period and then starts a new one. * - * @return StopwatchEvent The event. + * @return StopwatchEvent The event */ public function lap() { @@ -152,7 +152,12 @@ class StopwatchEvent return $this->formatTime($total); } - private function getNow() + /** + * Return the current time relative to origin. + * + * @return float Time in ms + */ + protected function getNow() { return $this->formatTime(microtime(true) * 1000 - $this->origin); } diff --git a/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php b/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php index aa78dbaacc..dbbb441889 100644 --- a/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php +++ b/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php @@ -87,14 +87,15 @@ class ProfilerListener implements EventSubscriberInterface return; } + $request = $event->getRequest(); $exception = $this->exception; $this->exception = null; - if (null !== $this->matcher && !$this->matcher->matches($event->getRequest())) { + if (null !== $this->matcher && !$this->matcher->matches($request)) { return; } - if (!$profile = $this->profiler->collect($event->getRequest(), $event->getResponse(), $exception)) { + if (!$profile = $this->profiler->collect($request, $event->getResponse(), $exception)) { return; } @@ -102,25 +103,20 @@ class ProfilerListener implements EventSubscriberInterface if (!$master) { array_pop($this->requests); - $parent = $this->requests[count($this->requests) - 1]; - if (!isset($this->children[$parent])) { - $profiles = array($profile); - } else { - $profiles = $this->children[$parent]; - $profiles[] = $profile; - } - + $parent = end($this->requests); + $profiles = isset($this->children[$parent]) ? $this->children[$parent] : array(); + $profiles[] = $profile; $this->children[$parent] = $profiles; } // store the profile and its children - if (isset($this->children[$event->getRequest()])) { - foreach ($this->children[$event->getRequest()] as $child) { + if (isset($this->children[$request])) { + foreach ($this->children[$request] as $child) { $child->setParent($profile); $profile->addChild($child); $this->profiler->saveProfile($child); } - $this->children[$event->getRequest()] = array(); + $this->children[$request] = array(); } $this->profiler->saveProfile($profile); diff --git a/src/Symfony/Component/HttpKernel/Profiler/PdoProfilerStorage.php b/src/Symfony/Component/HttpKernel/Profiler/PdoProfilerStorage.php index c87b8711f4..8e2bea4a44 100644 --- a/src/Symfony/Component/HttpKernel/Profiler/PdoProfilerStorage.php +++ b/src/Symfony/Component/HttpKernel/Profiler/PdoProfilerStorage.php @@ -91,22 +91,16 @@ abstract class PdoProfilerStorage implements ProfilerStorageInterface ':created_at' => time(), ); - if ($this->read($profile->getToken())) { - try { + try { + if ($this->read($profile->getToken())) { $this->exec($db, 'UPDATE sf_profiler_data SET parent = :parent, data = :data, ip = :ip, method = :method, url = :url, time = :time, created_at = :created_at WHERE token = :token', $args); - $this->cleanup(); - $status = true; - } catch (\Exception $e) { - $status = false; - } - } else { - try { + } else { $this->exec($db, 'INSERT INTO sf_profiler_data (token, parent, data, ip, method, url, time, created_at) VALUES (:token, :parent, :data, :ip, :method, :url, :time, :created_at)', $args); - $this->cleanup(); - $status = true; - } catch (\Exception $e) { - $status = false; } + $this->cleanup(); + $status = true; + } catch (\Exception $e) { + $status = false; } $this->close($db); diff --git a/src/Symfony/Component/HttpKernel/Profiler/Profiler.php b/src/Symfony/Component/HttpKernel/Profiler/Profiler.php index 966111c459..f2fc8a937a 100644 --- a/src/Symfony/Component/HttpKernel/Profiler/Profiler.php +++ b/src/Symfony/Component/HttpKernel/Profiler/Profiler.php @@ -157,7 +157,7 @@ class Profiler * @param Response $response A Response instance * @param \Exception $exception An exception instance if the request threw one * - * @return Profile|false A Profile instance or false if the profiler is disabled + * @return Profile|null A Profile instance or null if the profiler is disabled */ public function collect(Request $request, Response $response, \Exception $exception = null) { diff --git a/tests/Symfony/Tests/Component/HttpKernel/Debug/StopwatchTest.php b/tests/Symfony/Tests/Component/HttpKernel/Debug/StopwatchTest.php index 5675363eee..57d36f38c0 100644 --- a/tests/Symfony/Tests/Component/HttpKernel/Debug/StopwatchTest.php +++ b/tests/Symfony/Tests/Component/HttpKernel/Debug/StopwatchTest.php @@ -68,19 +68,19 @@ class StopwatchTest extends \PHPUnit_Framework_TestCase { $stopwatch = new Stopwatch(); - $stopwatch->startSection(); + $stopwatch->openSection(); $stopwatch->start('foo', 'cat'); $stopwatch->stop('foo'); $stopwatch->start('bar', 'cat'); $stopwatch->stop('bar'); $stopwatch->stopSection('1'); - $stopwatch->startSection(); + $stopwatch->openSection(); $stopwatch->start('foobar', 'cat'); $stopwatch->stop('foobar'); $stopwatch->stopSection('2'); - $stopwatch->startSection(); + $stopwatch->openSection(); $stopwatch->start('foobar', 'cat'); $stopwatch->stop('foobar'); $stopwatch->stopSection('0'); @@ -91,4 +91,31 @@ class StopwatchTest extends \PHPUnit_Framework_TestCase $this->assertCount(2, $stopwatch->getSectionEvents('2')); $this->assertCount(2, $stopwatch->getSectionEvents('0')); } + + public function testReopenASection() + { + $stopwatch = new Stopwatch(); + + $stopwatch->openSection(); + $stopwatch->start('foo', 'cat'); + $stopwatch->stopSection('section'); + + $stopwatch->openSection('section'); + $stopwatch->start('bar', 'cat'); + $stopwatch->stopSection('section'); + + $events = $stopwatch->getSectionEvents('section'); + + $this->assertCount(3, $events); + $this->assertCount(2, $events['__section__']->getPeriods()); + } + + /** + * @expectedException \LogicException + */ + public function testReopenANewSectionShouldThrowAnException() + { + $stopwatch = new Stopwatch(); + $stopwatch->openSection('section'); + } }