Profiling Silex controller actions in the Web Profiler timeline

The controller profiling problem

The WebProfilerServiceProvider brings the Symfony Profiler to Silex apps, and with it the nice "Timeline" feature, detailing for each request cycle the time spent handling each event dispatched by the EventDispatcher, from kernel.request to kernel.terminate, with detail time spent in each individual listener.

The timeline looks like this one. This is all nice and well, but there is a problem: although the beginning and end of the request cycle is profiled in depth, it represents less than half of the total time spent for this request.

More than half of the total request time is spent in the controller, and this example does not even perform any database access, which would make the controller represent event more of the total time, making the detailed analysis of the beginning and end of the request cycle less relevant.

What would make sense would be to subdivide the time spent in the controller in much the same way the time spent in the event listeners is already plotted. Is there a simple way, although the normal EventDispatcher is optimized and, as such, does not include any direct profiling point ?

The Silex/Symfony profiling mechanism

The normal dispatcher does not include any profiling support but, within Silex, the dispatcher is is actually instantiated as a Pimple service:

<?php// In Silex/Application.phpclass Application extends \Pimple implements HttpKernelInterface, TerminableInterface{// [...]    public function __construct(array $values = array())// [...]        $this['dispatcher_class'] = 'Symfony\\Component\\EventDispatcher\\EventDispatcher';        $this['dispatcher'] = $this->share(function () use ($app) {            $dispatcher = new $app['dispatcher_class']();// [...]}?>

This is a good thing, because it means that a provider can extend the optimized dispatcher and replace it cleanly by a profilable version, and this is exactly what WebProfilerServiceProvider does:

<?php// In Silex/Provider/WebProfilerServiceProvider.phpclass WebProfilerServiceProvider implements ServiceProviderInterface, ControllerProviderInterface{    public function register(Application $app)    {        $app['profiler.mount_prefix'] = '/_profiler';        $app['dispatcher'] = $app->share($app->extend('dispatcher', function ($dispatcher, $app) {            $dispatcher = new TraceableEventDispatcher($dispatcher, $app['stopwatch'], $app['logger']);            $dispatcher->setProfiler($app['profiler']);            return $dispatcher;        }));?>

The TraceableEventDispatcher thus introduced differs from the original dispatcher, notably in its EventDispatcherInterface::dispatch() implementation, which wraps a proxied call to EventDispatcher::dispatch() in preDispatch() and postDispatch() calls and Stopwatch calls, effectively collecting profiling data in the stopwatch service.

<?php// In Symfony/Component/HttpKernel/Debug/TraceableEventDispatcher.phpclass TraceableEventDispatcher implements EventDispatcherInterface, TraceableEventDispatcherInterface{// [...]    public function dispatch($eventName, Event $event = null)    {// [...]        $this->preDispatch($eventName, $event);// [...]        $e = $this->stopwatch->start($eventName, 'section');        $this->firstCalledEvent[$eventName] = $this->stopwatch->start($eventName.'.loading', 'event_listener_loading');// [...]        $this->dispatcher->dispatch($eventName, $event);// [...]        if ($e->isStarted()) {            $e->stop();        }// [...]        $this->postDispatch($eventName, $event);?>

The Symfony Stopwatch component

The Stopwatch component, introduced in Symfony 2.2, is described in the Symfony docs. In short, it allows millisecond-level timing of intervals of time, grouped in "sections", keeping the start and end time of each such interval to enable their placement on a timeline.

The WebProfilerServiceProvider instantiates it as a basic service, which the overridden dispatcher receives in its constructor as seen in the fragment above:

<?php// In Silex/Provider/WebProfilerServiceProvider.php    public function register(Application $app)    {// [...]        $app['stopwatch'] = $app->share(function () {            return new Stopwatch();        });// [...]?>

The preDispatch() and postDispatch in the TraceableEventDispatcher define periods based on the dispatched events and log time intervals for each event listener by start()ing and stop()ping the stopwatch around the proxy call to the base dispatch() as seen above. One such section is therefore created for the controller, as seen in the first image. But since in most cases, controller code will not be using the dispatcher itself, that section is not subdivided in intervals.

Implementing interval timing in controller actions

Since the stopwatch is a service on the Application object, controller actions can fetch the stopwatch instance used by the profiler from $app['stopwatch'], and record time intervals in the timeline like this:

<?phpclass SomeController {  // [...]  public function indexAction(Application $app, Request $req)  {    /** @var \Symfony\Component\Stopwatch\Stopwatch $stopwatch */    $stopwatch = $app['stopwatch'];    $e = $stopwatch->start('form');    // [...] do something form-related, then end the interval    $e->stop();    // Immediately start the next interval, building the response    $e = $stopwatch->start('twig');    // [...] rendering a Response    $e->stop();    // Immediately return the response.    return $response;  }?>

And that's all there is to it: the intervals in our action are now displayed in the profile timeline.

UPDATE 2014-02-05: to use the same Web Profiler toolbar in Drupal 8 projects instead of Silex, see http://blog.erdfisch.de/2014/02/webprofiler-toolbar-integration-drupal-8