Shopify/liquid — pull request #364 by jasonroelofs (2014-06-10 01:20:47+00:00)
Title: Profiling the rendering of a liquid template

This is an improved version of what I originally put together in #361

This PR adds a simple profiling system to liquid rendering. Each liquid tag ({{ }} and {% %}) is processed through this profiling, keeping track of the partial name (in the case of {% include %}), line number, and the time it took to render the tag. In the case of {% include %} and any tag that requires blocks (like {% if %} and {% for %}), the tags inside of the partials and blocks are themselves marked as children in the final profiling structure, letting any user of this information view top level information and to dive down into more details. With this, it's now possible to track down exactly which tags are taking a long time to render.

Included in this PR are internal changes to parsing to calculate and keep track of the line numbers of individual tags and tokens in the source, as well as some specific tracking of the current partial, such that using the include tag will be tracked as a nested render. I initially looked into adding this information to error exceptions but that was proving more complicated and would require quite a few changes to how tags handle syntax errors.

I was able to hook profiling into Liquid through one small refactoring (`Block#render_token`) and alias method chain-like hooks into the appropriate classes, significantly reducing the code impact on the core Liquid code base. There are also changes to parsing to figure out the line numbers of the tokens, Template to start up a profiling pass, and to Tags and Variables for easier output of the contents of these items when printing out the profiled information, but otherwise the actual profiling is kept separate. Because of this it would be trivial to also allow conditional loading with or without profiling, though not on a per-render basis, as these hooks do incur some cost and I'm unsure if it's possible to easily undo an alias chain like this.

The current profiling runs for these changes can be found here: https://gist.github.com/jasonroelofs/79bde3d22ede168a5ae8

I've also put together an example template and resulting profiling output here: https://gist.github.com/jasonroelofs/c8148317ffb09e541633

If you prefer not to have this in the core I would love to discuss what changes Liquid does need for this functionality to live as its own gem and hooking into Liquid when needed.