Skip to content

Profile the rendering time of a Template and its tags and tokens#361

Closed
jasonroelofs wants to merge 5 commits into
Shopify:masterfrom
collectiveidea:instrument-rendering
Closed

Profile the rendering time of a Template and its tags and tokens#361
jasonroelofs wants to merge 5 commits into
Shopify:masterfrom
collectiveidea:instrument-rendering

Conversation

@jasonroelofs
Copy link
Copy Markdown
Contributor

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.

Each token now is a Token object that is a String with line number
information.
This commit 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.
After running some profiling, it turns out that doing a variable lookup
in a Context is a slow operation, and doing that for every single tag
was significantly slowing down the system.
@fw42
Copy link
Copy Markdown
Contributor

fw42 commented May 30, 2014

ping @Shopify/liquid @Shopify/webscale, thoughts?

@jasonroelofs
Copy link
Copy Markdown
Contributor Author

Not sure why JRuby failed, possibly a timing issue.

I've been giving some thought to another way of implementing this, which would do some refactoring of Block#render to expose a hookable method (e.g. with alias_method_chain semantics) that would let this be less intrusive. Would probably have to refactor the Include tag a bit too. I also will play around with a String monkey-patch for line_number (over Liquid::Token) to see if that speeds things up again.

@jasonroelofs
Copy link
Copy Markdown
Contributor Author

I was able to come up with a much cleaner way of injecting this functionality. Closing this PR and will have another one available later tonight.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants