diogo/symfony
Archived
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

merged branch vicb/profiler.terminate (PR #3223)

Browse Source 
Commits
-------

3dd3d58 [EventListener] Fix an issue with sub-requests
71bf279 cleanup
acdb325 [StopWatch] Provide a cleaner API
acd1287 [Stopwatch] rename the section event to avoid collisions
eb540be [Profiler] Allow profiling the terminate event
4ccdc53 [HttpKernel] Cleanup of PdoProfilerStorage
814876f [HttpKernel] Tweak the code of the ProfilerListener

Discussion
----------

[Profiler] Allow profiling the terminate event

![Travis](https://secure.travis-ci.org/vicb/symfony.png?branch=profiler.terminate)

This PR is mainly about allowing to profile the terminate event (i.e. see it in the timeline panel)

There are some other tweaks.

---------------------------------------------------------------------------

by vicb at 2012-02-02T14:43:20Z

please don't merge for now. good question. bad answer.

---------------------------------------------------------------------------

by vicb at 2012-02-06T15:05:46Z

While first commits were focused on problem solving, the last brings a clean API with the ability to re-open an existing section in order to add events (re-setting event origins and merging them were just hacks).

Should be ready to be merged.

_Edit: Sorry, couldn't resist adding a private helper class again!_

---------------------------------------------------------------------------

by stof at 2012-02-06T18:30:09Z

@vicb you should stop adding such classes defined in the same file. Otherwise we will have to change the CS (and to stop telling we respect the PSR-0 standard)

---------------------------------------------------------------------------

by vicb at 2012-02-06T18:33:36Z

Once again PSR-0 is about autoloading which is exactly why I do not want in such cases. CS are an other matter and yes I think they should be changed to allow this (and I am going to submit a PR right now).

The only argument I could accept is whether this class should be private or not.

---------------------------------------------------------------------------

by vicb at 2012-02-06T19:57:06Z

Thanks for your valuable feedback @stof

---------------------------------------------------------------------------

by fabpot at 2012-02-11T20:53:03Z

Have you tested it on a project? Because it breaks my simple examples (where I have some sub-requests).

---------------------------------------------------------------------------

by vicb at 2012-02-12T09:47:23Z

my bad, should be ok now.
This commit is contained in:
Fabien Potencier 2012-02-12 13:12:18 +01:00
commit 7995b80bad
9 changed files with 269 additions and 103 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

52
src/Symfony/Bundle/FrameworkBundle/Debug/TraceableEventDispatcher.php
View File

@ -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

26
src/Symfony/Bundle/WebProfilerBundle/Resources/views/Collector/time.html.twig
View File

@ -64,14 +64,14 @@
<h3>
Main Request
<small>
- {{ collector.events.section.totaltime }} ms
- {{ collector.events.__section__.totaltime }} ms
{% if profile.parent %}
- <a href="{{ path('_profiler', { 'token': profile.parent.token }) }}?panel=time&threshold={{ threshold }}&width={{ width }}">parent</a>
- <a href="{{ path('_profiler', { 'token': profile.parent.token, 'panel': 'time', 'threshold': threshold, 'width': width }) }}">parent</a>
{% endif %}
</small>
</h3>
{% 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 %}
<h3>
Sub-request "<a href="{{ path('_profiler', { 'token': child.token }) }}?panel=time&threshold={{ threshold }}&width={{ width }}">{{ child.getcollector('request').requestattributes.get('_controller') }}</a>"
<small> - {{ events.section.totaltime }} ms</small>
Sub-request "<a href="{{ path('_profiler', { 'token': child.token, 'panel': 'time', 'threshold': threshold, 'width': width }) }}">{{ child.getcollector('request').requestattributes.get('_controller') }}</a>"
<small> - {{ events.__section__.totaltime }} ms</small>
</h3>
{{ _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 %}

11
src/Symfony/Component/HttpKernel/DataCollector/TimeDataCollector.php
View File

@ -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();
}
/**

191
src/Symfony/Component/HttpKernel/Debug/Stopwatch.php
View File

@ -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;
}
}
}

15
src/Symfony/Component/HttpKernel/Debug/StopwatchEvent.php
View File

@ -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);
}

22
src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php
View File

@ -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);

20
src/Symfony/Component/HttpKernel/Profiler/PdoProfilerStorage.php
View File

@ -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);

2
src/Symfony/Component/HttpKernel/Profiler/Profiler.php
View File

@ -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)
{

33
tests/Symfony/Tests/Component/HttpKernel/Debug/StopwatchTest.php
View File

@ -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');
}
}