As AppNeta’s developer evangelist, I work with customers in five different programming languages to monitor application performance. Drupal is just one part of one language, but I’ll always have a soft spot for it because it’s where I learned to program. When I get a chance, I like to keep my skills sharp by contributing to the community-maintained TraceView integration module. Last spring, I decided to port it and learn Drupal 8 the hard way.

Like most Drupal developers, I’d never tried writing Symfony code or using Composer to manage packages. Before attempting it, I decided to research both Symfony in its own right and how it is being leveraged to rewrite Drupal. Thankfully, there were many rich tutorials on “the basics” even then, and, after a relatively painless porting process, I had the module running with a skeletal Symfony bundle inside it.

Initially, I relied on the same strategy as the Drupal 7 version of the TraceView module, which monitors hook execution time by installing two additional modules: an “early” module with a very low weight and a “late” module with a very high weight. As each hook was removed from core, I moved its implementations from the modules into the bundle and tagged that event with listeners at maximum and minimum priority.

/**
 * Implements EventSubscriberInterface::getSubscribedEvents().
 */
static function getSubscribedEvents() {
  // Register before and after listeners for the primary kernel events.
  $events[KernelEvents::REQUEST][] = array('beforeRequest', 255);
  $events[KernelEvents::REQUEST][] = array('afterRequest', -255);
  $events[KernelEvents::VIEW][] = array('beforeView', 255);
  $events[KernelEvents::VIEW][] = array('afterView', -255);
  $events[KernelEvents::CONTROLLER][] = array('beforeController', 255);
  $events[KernelEvents::CONTROLLER][] = array('afterController', -255);
  $events[KernelEvents::RESPONSE][] = array('beforeResponse', 255);
  $events[KernelEvents::RESPONSE][] = array('afterResponse', -255);
  $events[KernelEvents::TERMINATE][] = array('beforeTerminate', 255);
  $events[KernelEvents::TERMINATE][] = array('afterTerminate', -255);
  // Exceptions are handled differently.
  $events[KernelEvents::EXCEPTION][] = array('onException', -255);
  return $events;
}

That mostly worked, but TraceView tracks calls by logging entry and exit events, and I was generating many entries with no matching exit. The shift away from Drupal’s familiar hooks to Symfony’s event listeners had caught me off guard: unlike Drupal hooks, which always run to completion, Symfony event listeners can call stopPropagation at any time to “consume” the event and prevent lower-priority listeners from responding!

My initial workaround was to turn the low-priority `view` listener into a high-priority listener on `response`, the event immediately afterwards. While error-prone, it was consistent enough to serve as an alpha. We kept this version running as our booth demo at DrupalCon Portland, much to the surprise of everyone who stopped by. I even got to meet the team from SensioLabs, who gave me some tips about how to improve the codebase.

When I came back to the module late that summer, I rewrote it to better account for Drupal's new architecture. Rather than just adding listeners to interesting kernel events, I used dependency injection (via traceview.services.yml) to replace the default Symfony event dispatcher with a subclass that wrapped the dispatch() method in TraceView API calls. This allowed for intercepting arbitrary events without having to know about them in advance, a significant improvement over my initial KernelEventSubscriber.

class TraceviewContainerAwareEventDispatcher extends ContainerAwareEventDispatcher
{
 
  /**
   * {@inheritDoc}
   *
   * Lazily loads listeners for this event from the dependency injection
   * container.
   *
   * @throws \InvalidArgumentException if the service is not defined
   */
  public function dispatch($eventName, Event $event = null)
  {
 
    // Check whether this is a kernel request or response.
    $is_request = ($eventName === "kernel.request");
    $is_response = ($eventName === "kernel.response");
 
    // On the start of a request, start a request layer.
    if ($is_request) {
      oboe_log(($event->getRequestType() === HttpKernelInterface::MASTER_REQUEST) ? 'HttpKernel.master_request' : 'HttpKernel.sub_request', "entry", array(), TRUE);
    }

    // Create a profile if the event has any listeners.
    if ($this->hasListeners($eventName)) {
      oboe_log("profile_entry", array('ProfileName' => $eventName), TRUE);
    }

    // Dispatch the event as normal.
    $ret = parent::dispatch($eventName, $event);

    // Capture controller/action information.
    if ($eventName === "kernel.controller") {
      $event_controller = $ret->getController();

      // Handle the closure case, as per LegacyControllerSubscriber.
      if (is_callable($event_controller) && is_object($event_controller)) {
        $router_item = $event->getRequest()->attributes->get('drupal_menu_item');
        $controller = $router_item['page_callback'];
        $action = (isset($router_item['page_arguments'][0])) ? $router_item['page_arguments'][0] : NULL;
        // Default to the object-based case.
      } else {
        $controller = $event_controller[0];
        $action = $event_controller[1];
      }
      // Report the C/A pair.
      oboe_log('info', array("Controller" => (is_object($controller)) ? get_class($controller) : $controller, "Action" => (is_object($action)) ? get_class($action) : $action));
    }
 
    // End the profile if the event has any listeners.
    if ($this->hasListeners($eventName)) {
      oboe_log("profile_exit", array('ProfileName' => $eventName));
    }
 
    // On the end of a response, stop the request layer.
    if ($is_response) {
      oboe_log(($event->getRequestType() === HttpKernelInterface::MASTER_REQUEST) ? 'HttpKernel.master_request' : 'HttpKernel.sub_request', "exit", array());
    }
 
    return $ret;
  }
}

While I was at DrupalCon Portland, multiple developers asked whether TraceView could be extended to monitor Twig performance. Since then, Twig was finalized as Drupal 8’s templating system, so I decided to give it my best shot. But since Twig isn’t based on HTTPKernel and doesn’t use kernel events, I couldn’t reuse my EventDispatcher subclass.

Instead, my first Twig instrumentation target was the TwigEnvironment class, which is a Drupalized wrapper around Twig that gets registered as the `twig` service. I created a TraceviewTwigEnvironment class with appropriate monitoring inserted into its render() and display() methods.

Unfortunately, this didn’t work. After some investigation, I realized that unlike the EventDispatcher, Twig isn’t registered in core.services.yml. Instead, it gets registered in CoreServiceProvider so that it can be used during installation, meaning that I had to add a ServiceProvider of my own containing a CompilerPass that did the same thing.

Even this provided inconsistent results though; in some cases templates were being called directly rather than through the environment’s helper functions. The best approach was to override the display() and render() methods of the templates themselves – effectively what I'd done for TwigEnvironment, but at a deeper level.

abstract class TraceviewTwigTemplate extends TwigTemplate {
  /**
   * {@inheritdoc}
   */
  public function display(array $context, array $blocks = array())
  {
    oboe_log("profile_entry", array('ProfileName' => $this->getTemplateName()), TRUE);
    $this->displayWithErrorHandling($this->env->mergeGlobals($context), $blocks);
    oboe_log("profile_exit", array('ProfileName' => $this->getTemplateName()));
  }
}

I updated to more recent alphas a few times that fall, but the next major adjustment came in early 2014. Another project had me revisiting the Symfony bundle that I had split off from the Drupal 8 module almost a year ago. After I made it available on Packagist, I decided to take code reuse in the other direction.
Unfortunately, the only way for a module to provide a Symfony bundle’s classes is to include them with the module, so I began by copying over the shiny new Symfony code. It was a welcome surprise to see that the only immediate adjustment I needed to make was namespace-related!
However, progress had indeed marched on.
By this point, I had refactored the TraceView bundle to reuse the Symfony web toolbar’s controller/action reporting code. This worked in Drupal, but it yielded less than satisfactory results because so many controllers are actually proxies. In fact, an HtmlPageController can be a proxy for something like an HtmlFormController, which itself is a proxy for a specific form! Unfortunately, filtering these cases to provide more human-friendly strings proved to be a tedious task.

/**
 * Parse a Symfony controller into a TraceView-reportable format.
 */
public function parseController($request, $controller) {
  $parsed = array('Controller' => NULL, 'Action' => NULL);

  // We use the same logic as the Symfony debug toolbar to parse out controller/action.
  if (is_array($controller)) {
    $parsed['Controller'] = $controller[0];
    $parsed['Action'] = $controller[1];
  } elseif ($controller instanceof \Closure) {
    $r = new \ReflectionFunction($controller);
    $parsed['Controller'] = $r->getName();
    $parsed['Action'] = NULL;
  } elseif (is_string($controller)) {
    // Controller::action strings
    if (strpos($controller, '::') !== FALSE) {
    $ca = explode("::", $controller);
    $parsed['Controller'] = $ca[0];
    $parsed['Action'] = $ca[1];
    // Any other string
  } else {
    $parsed['Controller'] = $controller;
  }

  // Proxy controller for a full HTML page. Re-parse the underlying controller.
  if (is_a($parsed['Controller'], 'Drupal\Core\Controller\HtmlPageController')) {
    return $this->parseController($request, $request->attributes->get("_content"));
  }

  // Proxy controller for an HTML form. Use the matching form
  // (e.g., 'Drupal\system\Form\ModulesListForm') as the action.
  if (is_a($parsed['Controller'], 'Drupal\Core\Controller\HtmlFormController')) {
    $parsed['Action'] = $request->attributes->get("_form");
  }

  // Proxy class for an HTML entity form. Use the matching entity form
  // (e.g., 'node.edit') as the action.
  if (is_a($parsed['Controller'], 'Drupal\Core\Entity\HtmlEntityFormController')) {
    $parsed['Action'] = $request->attributes->get("_entity_form");
  }
 
  // Proxy class for a View. Use the matching View ID and display ID.
  if ($parsed['Controller'] === 'Drupal\views\Routing\ViewPageController') {
    $parsed['Controller'] = 'ViewPageController::'.$request->attributes->get('view_id');
    $parsed['Action'] = $request->attributes->get('display_id');
  }

  return $parsed;
}

I’ve spent a decent amount of time diving into the guts of Drupal 8 over the past year, and I’ve learned more about it than I ever expected to. Even so, I wouldn’t say I feel comfortable using it, and my guess is that many Drupal developers will face a rough start given how many Drupalisms have been axed. On balance, this is probably good, but there’s a whole new set of concepts to internalize. Drupal 8 may be more logical and consistent than Drupal 7, but it’s downright sprawling in comparison.

On the other hand, Symfony developers shouldn’t expect to have a head start; Drupal 8 is not particularly Symfonic. Some Symfony standards, like bundles and routing, are just different enough to not apply here, and even the reused parts have a thick layer of Drupal on top. Your development will necessarily take place inside Drupal modules – and it’s not even possible to track their dependencies because they aren’t visible to Composer.

But is it a problem if neither set of developers feels at home in Drupal 8? Anyone writing Drupal code has already stuck around past the “learning cliff,” and it’s not clear that Drupal 8 being different has any relationship with it being hard. It’s reasonable to worry about where you’ll be by Day 30 – just don’t forget to wonder about what you’ll be building on Day 365.

Image: ©iStockphoto.com/emesilva