Reported by Peter Giles
I thought you would be interested in seeing this performace issue with calling functions from a
template. I ran into this because I was rendering a page with an ~850
element result set from a database query, and even though it was a very
simple page it was taking almost 10 seconds to merge. So I constructed
this example to try to figure out what is going on. It seems that in a
looping construct, function calls lead to a geometric runtime with
respect to the length of the list that is being iterated through, while
substitutions are in linear time. Here is my source file:
import airspeed, time
# function call
vm1 = '''#foreach ($elem in $mylist) $foo.bar() #end'''
# substitution
vm2 = '''#foreach ($elem in $mylist) $elem #end'''
# helper class used to get render timings
class Stopwatch:
def __init__(self):
self.start = time.time()
def stop(self):
self.stop = time.time()
def time(self):
return self.stop - self.start
class Foo:
def bar(self):
return 'hello'
def doTest(count, vm):
toMerge = {'mylist':range(count), 'foo':Foo()}
template = airspeed.Template(vm)
template.merge({}) # just to make sure the template is precompiled
sw = Stopwatch()
output = template.merge(toMerge)
sw.stop()
output = "list size: %s\trender time: %s seconds\tpage: %s" %
(count, sw.time(), vm)
print output
print '\nFunction calls:'
for c in [32,64,128,256,512]:
doTest(c, vm1)
print '\nSubstitutions:'
#for c in map(lambda x: 2**x, range(6,16)):
for c in [32,64,128,256,512]:
doTest(c, vm2)
Here's the output:
Function calls:
list size: 32 render time: 0.00718402862549 seconds page: #foreach
($elem in $mylist) $foo.bar() #end
list size: 64 render time: 0.0233280658722 seconds page: #foreach
($elem in $mylist) $foo.bar() #end
list size: 128 render time: 0.0994000434875 seconds page: #foreach
($elem in $mylist) $foo.bar() #end
list size: 256 render time: 0.462238073349 seconds page: #foreach
($elem in $mylist) $foo.bar() #end
list size: 512 render time: 2.34574079514 seconds page: #foreach
($elem in $mylist) $foo.bar() #end
Substitutions:
list size: 32 render time: 0.00999402999878 seconds page: #foreach
($elem in $mylist) $elem #end
list size: 64 render time: 0.00945997238159 seconds page: #foreach
($elem in $mylist) $elem #end
list size: 128 render time: 0.0117859840393 seconds page: #foreach
($elem in $mylist) $elem #end
list size: 256 render time: 0.0167841911316 seconds page: #foreach
($elem in $mylist) $elem #end
list size: 512 render time: 0.0261609554291 seconds page: #foreach
($elem in $mylist) $elem #end
The function calls are somehow causing recursion to occur, because if I
try and do the function calls test with 1024 elements, I get an
exception with a stack trace like this:
Traceback (most recent call last):
File "airspeed_test.py", line 40, in ?
doTest(c, vm1)
File "airspeed_test.py", line 31, in doTest
output = template.merge(toMerge)
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 48, in
merge
self.merge_to(namespace, output, loader)
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 58, in
merge_to
self.root_element.evaluate(fileobj, namespace, loader)
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 703,
in evaluate
self.block.evaluate(stream, namespace, loader)
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 715,
in evaluate
child.evaluate(stream, namespace, loader)
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 689,
in evaluate
self.block.evaluate(stream, namespace, loader)
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 715,
in evaluate
child.evaluate(stream, namespace, loader)
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 410,
in evaluate
value = self.expression.calculate(namespace, loader)
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 378,
in calculate
value = self.part.calculate(namespace, loader, global_namespace)
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 345,
in calculate
try: result = current_object[self.name]
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 137,
in __getitem__
except KeyError: return self.parent[key]
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 137,
in __getitem__
except KeyError: return self.parent[key]
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 137,
in __getitem__
except KeyError: return self.parent[key]
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 137,
in __getitem__
except KeyError: return self.parent[key]
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 137,
in __getitem__
except KeyError: return self.parent[key]
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 137,
in __getitem__
except KeyError: return self.parent[key]
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 137,
in __getitem__
except KeyError: return self.parent[key]
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 137,
in __getitem__
except KeyError: return self.parent[key]
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 137,
in __getitem__
except KeyError: return self.parent[key]
... (many pages of this) ...
File "/usr/local/lib/python2.4/site-packages/airspeed.py", line 137,
in __getitem__
except KeyError: return self.parent[key]
RuntimeError: maximum recursion depth exceeded
For contrast, I can easily call the substitution version on many more
elements and it processes fine, and extremely quickly (1.4 seconds for a
32768 element list).
