Shopify/liquid — pull request #361 by jasonroelofs (2014-05-30 20:29:23+00:00)
Title: Profile the rendering time of a Template and its tags and tokens

This PR adds a simple profiling system to liquid rendering. Each liquid tag ({{ }} and {% %}) are 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.

Some of this ended up being kind of messy, and I tried to keep the impact of these changes as minimal and contained as possible. Unfortunately the only objects that were accessible in all appropriate locations is the Context, and while it feels weird to have profiling there, anywhere else would have required much more significant changes.

I've run the various profiling and benchmarking tasks against these changes, starting with master and then two runs, one with profiling turned off and one with profiling turned on. I believe the biggest slow-down culprit here for both new cases are the new Liquid::Token objects to keep track of the line number of the curren token. I didn't want to monkey-patch String, but maybe that's the best way to go about this for speed purposes?

https://gist.github.com/jasonroelofs/56d48cbb5e0749ba3062

I would love some feedback on these changes and recommendations on other ways I may accomplish these changes.