From 814876fb12f19fe2bcdf573304d07856cbb7c952 Mon Sep 17 00:00:00 2001 From: Victor Berchet Date: Mon, 30 Jan 2012 13:58:23 +0100 Subject: [PATCH 1/7] [HttpKernel] Tweak the code of the ProfilerListener --- .../EventListener/ProfilerListener.php | 22 ++++++------------- .../HttpKernel/Profiler/Profiler.php | 2 +- 2 files changed, 8 insertions(+), 16 deletions(-) diff --git a/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php b/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php index aa78dbaacc..c0f240a0ea 100644 --- a/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php +++ b/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php @@ -87,40 +87,32 @@ 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; } // keep the profile as the child of its parent 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; - } - - $this->children[$parent] = $profiles; + $this->children[end($this->requests)][] = $profile; } // 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/Profiler.php b/src/Symfony/Component/HttpKernel/Profiler/Profiler.php index 966111c459..840529d9dc 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 false if the profiler is disabled */ public function collect(Request $request, Response $response, \Exception $exception = null) { From 4ccdc530bba8399f8e530d10699d4ffd2dfa612f Mon Sep 17 00:00:00 2001 From: Victor Berchet Date: Mon, 30 Jan 2012 14:27:45 +0100 Subject: [PATCH 2/7] [HttpKernel] Cleanup of PdoProfilerStorage --- .../Profiler/PdoProfilerStorage.php | 20 +++++++------------ 1 file changed, 7 insertions(+), 13 deletions(-) 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); From eb540bef29506dfb900d8c3fe43587bb1947e96b Mon Sep 17 00:00:00 2001 From: Victor Berchet Date: Mon, 30 Jan 2012 16:14:38 +0100 Subject: [PATCH 3/7] [Profiler] Allow profiling the terminate event --- .../Debug/TraceableEventDispatcher.php | 63 ++++++++++++++----- .../DataCollector/TimeDataCollector.php | 9 ++- .../HttpKernel/Debug/StopwatchEvent.php | 56 +++++++++++++++-- .../HttpKernel/Profiler/Profiler.php | 2 +- .../HttpKernel/Debug/StopwatchEventTest.php | 55 ++++++++++++++++ 5 files changed, 157 insertions(+), 28 deletions(-) diff --git a/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php b/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php index 823bce0082..fd2ccac9f2 100644 --- a/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php +++ b/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php @@ -49,14 +49,21 @@ 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->startSection(); + 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': + $this->stopwatch->startSection(); + break; } $e1 = $this->stopwatch->start($eventName, 'section'); @@ -65,14 +72,20 @@ 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': + $token = $event->getResponse()->headers->get('X-Debug-Token'); + $this->stopwatch->stopSection($token.'.terminate'); + $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,18 @@ class TraceableEventDispatcher extends ContainerAwareEventDispatcher implements return; } - $profile->getCollector('time')->setEvents($this->stopwatch->getSectionEvents($profile->getToken())); + $events = $this->stopwatch->getSectionEvents($token); + $origin = $events['section']->getOrigin(); + + foreach ($this->stopwatch->getSectionEvents($token.'.terminate') as $name => $event) { + if (isset($events[$name])) { + $events[$name]->merge($event); + } else { + $events[$name] = $event->setOrigin($origin); + } + } + + $profile->getCollector('time')->setEvents($events); $profiler->saveProfile($profile); // children diff --git a/src/Symfony/Component/HttpKernel/DataCollector/TimeDataCollector.php b/src/Symfony/Component/HttpKernel/DataCollector/TimeDataCollector.php index bdeb84cc3a..5d07ed2188 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,7 +82,7 @@ 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() { diff --git a/src/Symfony/Component/HttpKernel/Debug/StopwatchEvent.php b/src/Symfony/Component/HttpKernel/Debug/StopwatchEvent.php index f606f1bcd1..a389ddbb66 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 @@ -59,10 +59,51 @@ class StopwatchEvent return $this->origin; } + /** + * Updates the origin. + * + * @param float $origin The origin time in milliseconds + * + * @return StopwatchEvent The event + * + * @throws \InvalidArgumentException When the raw time is not valid + */ + public function setOrigin($origin) + { + $origin = $this->formatTime($origin); + $delta = $this->origin - $origin; + $this->origin = $origin; + foreach ($this->started as $i => $time) { + $this->started[$i] = $this->formatTime($time + $delta); + } + foreach ($this->periods as $i => $period) { + $this->periods[$i] = array( + $this->formatTime($period[0] + $delta), + $this->formatTime($period[1] + $delta) + ); + } + + return $this; + } + + /** + * Merges two events. + * + * @param StopWatchEvent $event The event to merge + * + * @return StopwatchEvent The event + */ + public function merge(StopWatchEvent $event) + { + $this->periods = array_merge($this->periods, $event->setOrigin($this->origin)->getPeriods()); + + return $this; + } + /** * Starts a new event period. * - * @return StopwatchEvent The event. + * @return StopwatchEvent The event */ public function start() { @@ -74,7 +115,7 @@ class StopwatchEvent /** * Stops the last started event period. * - * @return StopwatchEvent The event. + * @return StopwatchEvent The event */ public function stop() { @@ -90,7 +131,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 +193,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/Profiler/Profiler.php b/src/Symfony/Component/HttpKernel/Profiler/Profiler.php index 840529d9dc..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|null 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/StopwatchEventTest.php b/tests/Symfony/Tests/Component/HttpKernel/Debug/StopwatchEventTest.php index 9ec05e5284..f8d3ee59d5 100644 --- a/tests/Symfony/Tests/Component/HttpKernel/Debug/StopwatchEventTest.php +++ b/tests/Symfony/Tests/Component/HttpKernel/Debug/StopwatchEventTest.php @@ -149,4 +149,59 @@ class StopwatchEventTest extends \PHPUnit_Framework_TestCase { new StopwatchEvent("abc"); } + + public function testSetOrigin() + { + $event = $this + ->getMockBuilder('Symfony\\Component\\HttpKernel\\Debug\\StopwatchEvent') + ->setMethods(array('getNow')) + ->setConstructorArgs(array(0)) + ->getMock() + ; + + $event + ->expects($this->exactly(4)) + ->method('getNow') + ->will($this->onConsecutiveCalls(10, 20, 30, 40)) + ; + + $this->assertEquals( + array(array(0, 10), array(20, 40)), + $event->start()->stop()->start()->setOrigin(10)->stop()->getPeriods() + ); + } + + public function testMerge() + { + $e1 = $this + ->getMockBuilder('Symfony\\Component\\HttpKernel\\Debug\\StopwatchEvent') + ->setMethods(array('getNow')) + ->setConstructorArgs(array(0)) + ->getMock() + ; + + $e1 + ->expects($this->exactly(2)) + ->method('getNow') + ->will($this->onConsecutiveCalls(0, 10)) + ; + + $e2 = $this + ->getMockBuilder('Symfony\\Component\\HttpKernel\\Debug\\StopwatchEvent') + ->setMethods(array('getNow')) + ->setConstructorArgs(array(10)) + ->getMock() + ; + + $e2 + ->expects($this->exactly(2)) + ->method('getNow') + ->will($this->onConsecutiveCalls(50, 60)) + ; + + $this->assertEquals( + array(array(0, 10), array(60, 70)), + $e1->start()->stop()->merge($e2->start()->stop())->getPeriods() + ); + } } From acd1287d02b1c96281b368b32208dbe4c541d6e6 Mon Sep 17 00:00:00 2001 From: Victor Berchet Date: Tue, 31 Jan 2012 07:48:19 +0100 Subject: [PATCH 4/7] [Stopwatch] rename the section event to avoid collisions --- .../Debug/TraceableEventDispatcher.php | 2 +- .../Resources/views/Collector/time.html.twig | 22 +++++++++---------- .../DataCollector/TimeDataCollector.php | 4 ++-- .../Component/HttpKernel/Debug/Stopwatch.php | 8 +++---- 4 files changed, 18 insertions(+), 18 deletions(-) diff --git a/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php b/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php index fd2ccac9f2..33322aa126 100644 --- a/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php +++ b/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php @@ -266,7 +266,7 @@ class TraceableEventDispatcher extends ContainerAwareEventDispatcher implements } $events = $this->stopwatch->getSectionEvents($token); - $origin = $events['section']->getOrigin(); + $origin = $events['__section__']->getOrigin(); foreach ($this->stopwatch->getSectionEvents($token.'.terminate') as $name => $event) { if (isset($events[$name])) { 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..b7aa90004b 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 {% endif %}

- {% set max = collector.events.section.endtime %} + {% set max = collector.events.__section__.endtime %} {{ _self.display_timeline('timeline_' ~ token, collector.events, threshold, colors, width) }} @@ -80,7 +80,7 @@ {% set events = child.getcollector('time').events %}

Sub-request "{{ child.getcollector('request').requestattributes.get('_controller') }}" - - {{ events.section.totaltime }} ms + - {{ 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 5d07ed2188..a91e91c78c 100644 --- a/src/Symfony/Component/HttpKernel/DataCollector/TimeDataCollector.php +++ b/src/Symfony/Component/HttpKernel/DataCollector/TimeDataCollector.php @@ -72,7 +72,7 @@ class TimeDataCollector extends DataCollector */ public function getTotalTime() { - $lastEvent = $this->data['events']['section']; + $lastEvent = $this->data['events']['__section__']; return $lastEvent->getOrigin() + $lastEvent->getTotalTime() - $this->data['start_time']; } @@ -86,7 +86,7 @@ class TimeDataCollector extends DataCollector */ 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..2d66995c23 100644 --- a/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php +++ b/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php @@ -29,14 +29,14 @@ class Stopwatch public function startSection() { if ($this->events) { - $this->start('section.child', 'section'); + $this->start('__section__.child', 'section'); $this->waiting[] = array($this->events, $this->origin); $this->events = array(); } $this->origin = microtime(true) * 1000; - $this->start('section'); + $this->start('__section__'); } /** @@ -50,7 +50,7 @@ class Stopwatch */ public function stopSection($id) { - $this->stop('section'); + $this->stop('__section__'); if (null !== $id) { $this->sections[$id] = $this->events; @@ -58,7 +58,7 @@ class Stopwatch if ($this->waiting) { list($this->events, $this->origin) = array_pop($this->waiting); - $this->stop('section.child'); + $this->stop('__section__.child'); } else { $this->origin = null; $this->events = array(); From acdb3250675dad07bc2fb977a5672264507a06ac Mon Sep 17 00:00:00 2001 From: Victor Berchet Date: Mon, 6 Feb 2012 15:51:54 +0100 Subject: [PATCH 5/7] [StopWatch] Provide a cleaner API --- .../Debug/TraceableEventDispatcher.php | 21 +- .../Component/HttpKernel/Debug/Stopwatch.php | 191 +++++++++++++++--- .../HttpKernel/Debug/StopwatchEvent.php | 41 ---- .../HttpKernel/Debug/StopwatchEventTest.php | 55 ----- .../HttpKernel/Debug/StopwatchTest.php | 33 ++- 5 files changed, 195 insertions(+), 146 deletions(-) diff --git a/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php b/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php index 33322aa126..c2116ea663 100644 --- a/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php +++ b/src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php @@ -51,7 +51,7 @@ class TraceableEventDispatcher extends ContainerAwareEventDispatcher implements { switch ($eventName) { case 'kernel.request': - $this->stopwatch->startSection(); + $this->stopwatch->openSection(); break; case 'kernel.view': case 'kernel.response': @@ -62,7 +62,8 @@ class TraceableEventDispatcher extends ContainerAwareEventDispatcher implements } break; case 'kernel.terminate': - $this->stopwatch->startSection(); + $token = $event->getResponse()->headers->get('X-Debug-Token'); + $this->stopwatch->openSection($token); break; } @@ -82,8 +83,7 @@ class TraceableEventDispatcher extends ContainerAwareEventDispatcher implements $this->updateProfile($token); break; case 'kernel.terminate': - $token = $event->getResponse()->headers->get('X-Debug-Token'); - $this->stopwatch->stopSection($token.'.terminate'); + $this->stopwatch->stopSection($token); $this->updateProfile($token); break; } @@ -265,18 +265,7 @@ class TraceableEventDispatcher extends ContainerAwareEventDispatcher implements return; } - $events = $this->stopwatch->getSectionEvents($token); - $origin = $events['__section__']->getOrigin(); - - foreach ($this->stopwatch->getSectionEvents($token.'.terminate') as $name => $event) { - if (isset($events[$name])) { - $events[$name]->merge($event); - } else { - $events[$name] = $event->setOrigin($origin); - } - } - - $profile->getCollector('time')->setEvents($events); + $profile->getCollector('time')->setEvents($this->stopwatch->getSectionEvents($token)); $profiler->saveProfile($profile); // children diff --git a/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php b/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php index 2d66995c23..6144b97744 100644 --- a/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php +++ b/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php @@ -18,24 +18,33 @@ 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) { + if (false === $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__.child', 'section'); + $this->activeSections[] = $current->open($id); $this->start('__section__'); } @@ -52,17 +61,12 @@ class Stopwatch { $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 +78,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 Symfony\Component\HttpKernel\Debug\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 Symfony\Component\HttpKernel\Debug\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|false The child section or false when none found + */ + public function get($id) + { + foreach ($this->children as $child) { + if ($id === $child->getId()) { + return $child; + } + } + + return false; + } + + /** + * 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 (false === $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 Symfony\Component\HttpKernel\Debug\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 +214,11 @@ class Stopwatch * * @param string $name The event name * - * @return StopwatchEvent A StopwatchEvent instance + * @return Symfony\Component\HttpKernel\Debug\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 +228,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 Symfony\Component\HttpKernel\Debug\StopwatchEvent The event + * + * @throws \LogicException When the event has not been started */ public function lap($name) { @@ -111,14 +242,12 @@ class Stopwatch } /** - * Gets all events for a given section. + * Returns the events from this section. * - * @param string $id A section identifier - * - * @return StopwatchEvent[] An array of StopwatchEvent instances + * @return Symfony\Component\HttpKernel\Debug\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 a389ddbb66..70b6a5e74f 100644 --- a/src/Symfony/Component/HttpKernel/Debug/StopwatchEvent.php +++ b/src/Symfony/Component/HttpKernel/Debug/StopwatchEvent.php @@ -59,47 +59,6 @@ class StopwatchEvent return $this->origin; } - /** - * Updates the origin. - * - * @param float $origin The origin time in milliseconds - * - * @return StopwatchEvent The event - * - * @throws \InvalidArgumentException When the raw time is not valid - */ - public function setOrigin($origin) - { - $origin = $this->formatTime($origin); - $delta = $this->origin - $origin; - $this->origin = $origin; - foreach ($this->started as $i => $time) { - $this->started[$i] = $this->formatTime($time + $delta); - } - foreach ($this->periods as $i => $period) { - $this->periods[$i] = array( - $this->formatTime($period[0] + $delta), - $this->formatTime($period[1] + $delta) - ); - } - - return $this; - } - - /** - * Merges two events. - * - * @param StopWatchEvent $event The event to merge - * - * @return StopwatchEvent The event - */ - public function merge(StopWatchEvent $event) - { - $this->periods = array_merge($this->periods, $event->setOrigin($this->origin)->getPeriods()); - - return $this; - } - /** * Starts a new event period. * diff --git a/tests/Symfony/Tests/Component/HttpKernel/Debug/StopwatchEventTest.php b/tests/Symfony/Tests/Component/HttpKernel/Debug/StopwatchEventTest.php index f8d3ee59d5..9ec05e5284 100644 --- a/tests/Symfony/Tests/Component/HttpKernel/Debug/StopwatchEventTest.php +++ b/tests/Symfony/Tests/Component/HttpKernel/Debug/StopwatchEventTest.php @@ -149,59 +149,4 @@ class StopwatchEventTest extends \PHPUnit_Framework_TestCase { new StopwatchEvent("abc"); } - - public function testSetOrigin() - { - $event = $this - ->getMockBuilder('Symfony\\Component\\HttpKernel\\Debug\\StopwatchEvent') - ->setMethods(array('getNow')) - ->setConstructorArgs(array(0)) - ->getMock() - ; - - $event - ->expects($this->exactly(4)) - ->method('getNow') - ->will($this->onConsecutiveCalls(10, 20, 30, 40)) - ; - - $this->assertEquals( - array(array(0, 10), array(20, 40)), - $event->start()->stop()->start()->setOrigin(10)->stop()->getPeriods() - ); - } - - public function testMerge() - { - $e1 = $this - ->getMockBuilder('Symfony\\Component\\HttpKernel\\Debug\\StopwatchEvent') - ->setMethods(array('getNow')) - ->setConstructorArgs(array(0)) - ->getMock() - ; - - $e1 - ->expects($this->exactly(2)) - ->method('getNow') - ->will($this->onConsecutiveCalls(0, 10)) - ; - - $e2 = $this - ->getMockBuilder('Symfony\\Component\\HttpKernel\\Debug\\StopwatchEvent') - ->setMethods(array('getNow')) - ->setConstructorArgs(array(10)) - ->getMock() - ; - - $e2 - ->expects($this->exactly(2)) - ->method('getNow') - ->will($this->onConsecutiveCalls(50, 60)) - ; - - $this->assertEquals( - array(array(0, 10), array(60, 70)), - $e1->start()->stop()->merge($e2->start()->stop())->getPeriods() - ); - } } 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'); + } } From 71bf279e9f9f70fafe2d84360087398f87854f3b Mon Sep 17 00:00:00 2001 From: Victor Berchet Date: Mon, 6 Feb 2012 20:51:05 +0100 Subject: [PATCH 6/7] cleanup --- .../Component/HttpKernel/Debug/Stopwatch.php | 24 +++++++++---------- 1 file changed, 11 insertions(+), 13 deletions(-) diff --git a/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php b/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php index 6144b97744..b4de49ba99 100644 --- a/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php +++ b/src/Symfony/Component/HttpKernel/Debug/Stopwatch.php @@ -37,10 +37,8 @@ class Stopwatch { $current = end($this->activeSections); - if (null !== $id) { - if (false === $current->get($id)) { - throw new \LogicException(sprintf('The section "%s" has been started at an other level and can not be opened.', $id)); - } + 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->start('__section__.child', 'section'); @@ -99,7 +97,7 @@ class Stopwatch * * @param string $name The event name * - * @return Symfony\Component\HttpKernel\Debug\StopwatchEvent A StopwatchEvent instance + * @return StopwatchEvent A StopwatchEvent instance */ public function lap($name) { @@ -111,7 +109,7 @@ class Stopwatch * * @param string $id A section identifier * - * @return Symfony\Component\HttpKernel\Debug\StopwatchEvent[] An array of StopwatchEvent instances + * @return StopwatchEvent[] An array of StopwatchEvent instances */ public function getSectionEvents($id) { @@ -141,7 +139,7 @@ class Section * * @param string $id The child section identifier * - * @return Section|false The child section or false when none found + * @return Section|null The child section or null when none found */ public function get($id) { @@ -151,7 +149,7 @@ class Section } } - return false; + return null; } /** @@ -163,7 +161,7 @@ class Section */ public function open($id) { - if (false === $session = $this->get($id)) { + if (null === $session = $this->get($id)) { $session = $this->children[] = new self(microtime(true) * 1000); } @@ -198,7 +196,7 @@ class Section * @param string $name The event name * @param string $category The event category * - * @return Symfony\Component\HttpKernel\Debug\StopwatchEvent The event + * @return StopwatchEvent The event */ public function startEvent($name, $category) { @@ -214,7 +212,7 @@ class Section * * @param string $name The event name * - * @return Symfony\Component\HttpKernel\Debug\StopwatchEvent The event + * @return StopwatchEvent The event * * @throws \LogicException When the event has not been started */ @@ -232,7 +230,7 @@ class Section * * @param string $name The event name * - * @return Symfony\Component\HttpKernel\Debug\StopwatchEvent The event + * @return StopwatchEvent The event * * @throws \LogicException When the event has not been started */ @@ -244,7 +242,7 @@ class Section /** * Returns the events from this section. * - * @return Symfony\Component\HttpKernel\Debug\StopwatchEvent[] An array of StopwatchEvent instances + * @return StopwatchEvent[] An array of StopwatchEvent instances */ public function getEvents() { From 3dd3d582c4adfd766802506dd156dc3f8c2bdeca Mon Sep 17 00:00:00 2001 From: Victor Berchet Date: Sun, 12 Feb 2012 10:02:50 +0100 Subject: [PATCH 7/7] [EventListener] Fix an issue with sub-requests --- .../Resources/views/Collector/time.html.twig | 4 ++-- .../Component/HttpKernel/EventListener/ProfilerListener.php | 6 +++++- 2 files changed, 7 insertions(+), 3 deletions(-) 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 b7aa90004b..6a97c900b5 100644 --- a/src/Symfony/Bundle/WebProfilerBundle/Resources/views/Collector/time.html.twig +++ b/src/Symfony/Bundle/WebProfilerBundle/Resources/views/Collector/time.html.twig @@ -66,7 +66,7 @@ - {{ collector.events.__section__.totaltime }} ms {% if profile.parent %} - - parent + - parent {% endif %} @@ -79,7 +79,7 @@ {% for child in profile.children %} {% set events = child.getcollector('time').events %}

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

diff --git a/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php b/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php index c0f240a0ea..dbbb441889 100644 --- a/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php +++ b/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php @@ -102,7 +102,11 @@ class ProfilerListener implements EventSubscriberInterface // keep the profile as the child of its parent if (!$master) { array_pop($this->requests); - $this->children[end($this->requests)][] = $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