This is basically a "Blog Post".
My sysadmin came in and told me about how slow the site was running now. He got tired of spinning up new instances and tweaking the cache. Our contributors were also complaining about how slow the content adds and edits were going. Those complaints are really bad, because the whole organization will now think Plone is horrible and we need a different CMS.
So, I was tasked with making things faster.
Also, I was given some hints:
Removing the "twitter card" and "open graph" tags from the page template would significantly improve performance.
Requesting and rendering a "Story" (much like the default document type) would also render the main portal page.
This is just weird, and wrong. So I took out the big guns (cProfile and kCacheGrind) and started profiling our TAL templates.
For background, note we use TAL/METAL exclusively for all our templating needs at RFA, but the lessons learned here can certainly be applied to chamelion + diazo implementations.
Without going into the whole "how to profile" subject, which is a talk in itself, I'll jump right to the conclusion and best practice result:
Don't use a TAL path expressions when you can use a python expression
-- Phillip Bauer
and a bit more specific:
Never, ever use a TAL expression in a tal:condition
-- Me
This might be a bit broad, there may be cases where you want to break that rule, but you should know exactly why you are breaking that rule, and have a very strong understanding about how TAL expressions are evaluated before breaking it.
So, how can a simple "twitter card" bring a Plone site to it's knees? That sounds kind of severe, doesn't it?
Consider this handy macro that gets pulled into stories, so we get pretty twitter cards when our stories are shared on twitter:
<metal:macro metal:define-macro="story_twitter">
<tal:x tal:define="image context/getFeaturedImage | nothing;
description context/Description;
text context/text">
<meta property="twitter:card" content="summary_large_image"/>
<meta property="twitter:site" content="@RadioFreeAsia"/>
<meta property="twitter:url" content=""
tal:attributes="content context/absolute_url"/>
<meta property="twitter:domain" content="rfa.org"/>
<meta property="twitter:title" content=""
tal:attributes="content context/Title"/>
<meta property="twitter:description" content=""
tal:condition="description"
tal:attributes="content description"/>
<meta property="twitter:description" content=""
tal:condition="not: description"
tal:attributes="content text"/>
<tal:if tal:condition="image">
<meta property="twitter:image" content=""
tal:attributes="content image/absolute_url"/>
<meta property="twitter:image:src" content=""
tal:attributes="content image/absolute_url"/>
</tal:if>
</tal:x>
</metal:macro>
Seems pretty straight forward. The context is a story, we get the story's image, it's descrption, text, and it's url. Then we just fill out the twitter card meta tags.
We also conditionally add an image property, because we might not have an image.
We don't even use a browser view - we just use the context.
The 'image' is an image object, not brains - because it might be scaled. (hint hint)
If we add this macro to our story, it will double the page load time.
What's Going On Here?
How can such simple code cause such a load on the site?
Well, cProfile said that I was spending a whole bunch of time in 'tal:condition'
That doesn't make sense... are you None or are you not? That should be super fast.
cProfile also said I was rendering the main template all over again.
Digging deeper, I was rendering our default view of an image, which I discovered is some strange template somewhere I still haven't found that happily adds a header, footer, featured stories, and all sorts of crap just to show you an image.
If you haven't figured it out yet, %99 of the work is done here:
<tal:if tal:condition="image">
Why?
Because:
- It's a TAL expression and
- 'image' is callable.
if you 'call' and object, you set off a ton of work looking for a default view of that object, finding a template, and rendering that object in HTML.
This line eventually, after a few million CPU cycles, results in this:
<tal:if tal:condition="python:str('<!DOCTYPE HTML PUBLIC ..... and a really long string of HTML')
Which evaluates to True
- because it is not an empty string
(cue laughter)
This is the most wonderfully inefficient way to cast an object to a bool I have ever encountered in my career.
This is also the most awesome violation of the 'explicit is better than implicit' philosophy of python: If you want to 'call' something, you should explicitly 'call' it.
TAL takes a different approach: If you don't want to call something, explicitly don't call it: add nocall:
<tal:if tal:condition="nocall:image">
Wow, I just sped up our site by a whole factor of two!
Now back to what Phillip Bauer said, and put it to practice:
<tal:if tal:condition="python:image">
Or even better for those who like to be explicit - like me:
<tal:if tal:condition="python:image is not None">
From here, I cleaned up the entire macro - making everything a python expression where I could.
I then searched through all my templates for such behavior, and found that I have been doing this kind of thing way too often to admit.
Just this one kind of 'bare object token' in TAL - removing this one kind of sin, has sped up our site by over a factor of 10.
I would consider this part of Donald Knuth's "critical 3%" that should not be overlooked when using TALES
Quite embarrassing, but at the same time, quite a relief that it's not Plone's fault - it's my own.
No, I'll blame it on the TAL syntax - that sounds better.
If interested, I'll add another post on how to do performance testing on templates. It's not hard.