Improved template error messages

[rjwittams]

Template errors are annoying to find. This patch adds filename and line numbers to the error messages when the DEBUG setting is true.

Extracted from the new-admin branch.

[rjwittams]

patch. Apply in the directory django/core/

[Adrian Holovaty]

At first glance, I don't like adding that much code to tokenize(). Seems like it would slow down template compilation. Have you benchmarked this against the existing template system?

This is precisely why, when we wrote the template system, we intentionally avoided keeping track of line numbers. It was too much of an unneeded performance loss.

[C8E]

What do you think about using

if DEBUG:

to conditionally enable this useful feature? In debug mode who cares of a little slow down, if it gives you more information about what's goin' on?

[robert@…]

How about we actually find out what the performance impact is before dismissing it out of hand?

[Adrian Holovaty]

Robert: That's why I asked whether you'd benchmarked it. :)

[robert@…]

With this (copying the different copies of template.py to template_old and template_new) :

import timeit

t = open("admin_change_form.html").read()

old = timeit.Timer('tokenize(t)',
                   'from template_old import tokenize; from __main__ import t')
new = timeit.Timer('tokenize(t, "name")',
                   'from template_new import tokenize; from __main__ import t')

old_time = old.timeit(number=20000)
new_time = new.timeit(number=20000)

print "Old %s, new %s " % (old_time, new_time)

I get:

Old 19.277905941, new 33.4315948486

So a slightly more than 50% slowdown. Of course this says nothing about the impact in the real world with caching etc, and I really doubt this has a significant impact on overall runtime.

[robert@…]

Ok, so I did some profiling using django-admin.py ( turned off the autoreloader as profile.py seems confused by threads).
This wasn't very scientific, and not a comparison, just wanted to get an idea of how much time is spent in tokenize.

So after messing about for a while, clicking around in the admin, it turns out that out of a CPU time of 3.5 seconds, 0.07 was used in tokenize. So if the penalty above holds, we are talking about a penalty of around 0.7% with no caching, in a very template heavy setting ( the new admin system, which does a lot of template inclusion via custom tags, no caching of compilation even in the same request at the moment) What do people think about that?

One surprise when I first looked at the template system: I didn't find anywhere compiled templates are cached, as half implied at:

​http://www.djangoproject.com/documentation/templates_python/

---

_Behind the scenes_

The system only parses your raw template code once -- when you create the Template object. From then on, it's stored internally as a "node" structure for performance.

---

I think we should change this somehow. Reading this I was expecting compilation to only occur when the file changed, ie caching between requests. I get why that reading is wrong, but currently it makes it sound a lot better than it really is. (Almost every template is going to be compiled once and rendered once.) I think some form of optional compiled template caching would be possible and desirable in future, eg via memcached ( Or am I missing something?)

One thing that popped out during profiling was that parsing filters is taking quite long, possibly due to function call overhead ( at least a call to next_char for every character.) Could probably save more time there, and this is per render rather than at compile time.

[Jacob]

"""
I think some form of optional compiled template caching would be possible and desirable in future, eg via memcached ( Or am I missing something?)
"""

Yes, actually -- turns out that the cost of a cache miss is *more* than the cost of compiling a template (we profiled this about a year ago, so it may have changed in the meantime). So it turns out it's easier to just parse the template when it's needed. Premature optimization, and all that. Still, optional template caching might be a speed increase in some situations -- say, a given view gets hit far more often than others -- so I'm more than open to suggestions.

Great point about parsing filters -- I imagine there's a similar issue with template tag calls, as well. Stupid function call overhead... any ideas?

[robert@…]

"turns out that the cost of a cache miss is *more* than the cost of compiling a template"

Erm: a cache miss would be compiling a template + finding out it was a miss, so I would expect it to cost more than just the former... do you mean a hit?

I can't see any obvious way to reduce the overhead for template tags without making them suck. Also, they didn't show up as a big issue afaik. The filter stuff could certainly be done in loops etc.

[rjwittams]

updated patch

[rjwittams]

Ok, so I gave in and made this just an option that gets enabled when DEBUG = true.

encapsulated tokenize and create_token in a Lexer class, then subclassed Lexer and Parser for debugging specific behaviour. So now this has no performance hit when people are not debugging.

Robert