X
    Categories Performance Monitoring

TraceView’s Oboe Symfony No. 2

AppNeta no longer blogs on DevOps topics like this one.

Feel free to enjoy it, and check out what we can do for monitoring end user experience of the apps you use to drive your business at www.appneta.com.

In my last post, I looked at how Drupal 8′s move to Symfony would change, well, everything. Edge side includes, new events like terminate, and more pave the way for some really excellent improvements in Drupal, both for performance and maintainability. This time, let’s look at what it takes to measure the internals of Symfony.

On the shoulders of giants

TraceView’s PHP extension, `php_oboe`, can collect data about anything from a CLI script to a load balanced CMS without code modification. But in some cases, like with our Drupal module or Zend hook, we augment the information collected by the extension with our PHP API. Our Symfony bundle, released to coincide with our trip to DrupalCon due to the adoption of Symfony for Drupal 8, is the newest addition to that family. When I wrote about it last time, it was with a focus on changes being made in Drupal 8 and how they’re informed by its adoption of Symfony; this time around, though, I’ll be covering the development process of the bundle.

I did a lot of research about Symfony prior to starting on the bundle, but when I started coding, I tried to leverage existing work whenever possible. At the time I started this project, Drupal 8 modules would autoload Symfony bundles placed inside of them. I only had to made a handful of edits to our module’s 7.x-1.x branch before it was running smoothly on Drupal 8, so I used that as a starting point – though I did make sure to turn off the module’s Drupal-specific data collection in order to better focus on collecting information that would work on any Symfony site.

To collect Drupal layer data like `drupal_views`, we require two additional modules to be installed: an ‘early’ module with a very low weight and a ‘late’ module with a very high weight. Since every module gets a chance to respond to every hook, this ensures that the layers in TraceView will be correctly matched up with the beginning and end of the `module_implements` calls. I applied this same approach in the bundle by creating event listeners that reported entry events at maximum priority and exit events at minimum priority. This was a little challenging, as there aren’t many well-documented examples of event listeners yet, but I was able to lift heavily from core’s source code. An hour or two of research later and I had a reasonable instrumentation of Symfony’s HTTPKernel:

Creating separate layers for `HTTPKernelInterface::MASTER_REQUEST` and `HTTPKernelInterface::SUB_REQUEST` permits easy understanding of even very complicated Symfony traces.

I was quite pleased with how this basic implementation (pictured above) worked out! It wasn’t until I was just about ready to release an alpha that I noticed a major bug:

(╯°□°)╯︵ ┻━┻

Wait, I’m not done!

Our trace parser is robust, but occasionally someone will send it something that it can’t figure out. This results in a ‘broken trace’, and in this case inspecting the raw trace data revealed that the root cause was issuing layer entry events without matching layer exit events. When I looked into this problem deeper, I realized that I hadn’t seen this problem until late in the development process because it only affected the ‘late’ (-255 priority) `view` listener, and only on certain pages of the site to boot. I was quite confused by that discovery – why would a listener fail some of the time?

As it turns out, I’d missed a critical subtlety in Symfony event listeners. Unlike Drupal hooks, which always run to completion, Symfony event listeners can call `stopPropagation` to ‘consume’ the event and prevent any lower-priority listeners from responding. This means that the ‘early’/’late’ pattern that works so well for the TraceView Drupal module doesn’t map cleanly to Symfony, since the ‘late’ listener might never get a chance to fire.

In the long term, I’ll have to resolve this problem by overriding some of the behavior of the Symfony event framework, possibly by adding a compiler pass to change how the dependency injection container is compiled from its constituent classes. That’s a bit outside the scope of this blog post, though, so for now I’ve introduced an admittedly ugly workaround into the TraceView bundle (isn’t that what beta is for?): the low-priority `view` exit event was set as a high-priority listener on the event processed afterwards, `response`. This let me see the `view` profile that I’d been missing, but more importantly, it prevented broken traces by ensuring that an entry into a layer is always paired with a corresponding exit.

The bundle’s current iteration is simple, but much of that is a choice driven by parsimony. I only needed to add a handful of new layers (via just a single new PHP class) to tell a much richer story about my Symfony application. Check out the before and after screenshots for the performance problem that I ran into last time:

Even without code modification, TraceView picked up on a high number of `file_get_contents` calls on each request.

The bundle placed those `file_get_contents` calls in the context of Symfony’s request flow – all on a single pane of glass.

Simple or not, I still learned a lot about both Symfony and Drupal 8 in the process of creating the bundle. It was hard keeping up with Drupal 8′s changing API, and I had to pull an all-nighter the weekend before DrupalCon rebasing changes to get everything running on the most recent version, but in the end it was worth it. The demo was well-received, and I’ve been able to reuse the demo site when talking to both Drupal and Symfony developers to illustrate what we’re able to pick up on in TraceView.

Twig and More

What’s next for TraceView and Symfony? We’ll be expanding instrumentation beyond HTTPKernel to collect additional details about some of the more popular components. At DrupalCon, several developers approached us about using TraceView to monitor Twig performance. Given our existing supported for nested partials in Ruby on Rails, we’re already confident that we’ll be able to expand our monitoring to include this exciting templating system. We also want to explore integration with Symfony’s existing monitoring tools, such as letting you use the Symfony developer toolbar to get from any page to the trace that generated it.

Of course, while our bundle will work on any Symfony site, we’ll be paying special attention to how our Symfony support will affect the next version of our Drupal support. As I noted previously, Drupal 8 hasn’t hit code freeze, and some major architectural changes involving the DrupalKernel nixed the approach I used while building the bundle of relying on module autoloading of bundles. The only workaround I could find was to manually register the bundle via a settings.php modification and then declare one of its classes as a service within the module’s `services.yml` file. It would be unfortunate if future interoperability between Drupal and Symfony required that kind of workaround, so I’ve posted a writeup of the problem on drupal.org in the hopes that it can be resolved before the code freeze.

James Meickle: James started as a hobbyist web developer, even though his academic background is in social psychology and political science. His favorite language is Python, his favorite editor is Sublime, and his favorite game is Dwarf Fortress.