How to profile a Jinja2 template?

Question

The Flask app I am profiling spends a long time rendering its Jinja2 templates.

I have installed flask lineprofilerpanel which is interesting but unfortunately does not let me drill down into the template rendering to see where all the time is spent.

What is the best way to profile a Jinja2 template?

Answer 1

Great question. I don't normally have much use for a profiler so this was a good excuse to learn. Following the example here: https://docs.python.org/2/library/profile.html#module-cProfile I coded up a simple example of profiling a jinja template.

import cProfile as profile
import pstats
import StringIO

import jinja2
import time

pr = profile.Profile()

def slow():
    time.sleep(2)
    return "Booga!"

template = jinja2.Template(r'''
    {% for i in RANGE1 %}<h1>hello world {{ i}}</h1>{% endfor %}
    {% for i in RANGE2 %}<h1>foo bar {{ i}}</h1>{% endfor %}
    {{ SLOW() }}
        '''
        )

# here is the bit we want to profile
pr.enable()
context = {"RANGE1": range(1000000), "RANGE2":range(100), "SLOW":slow}
template.render(context)
pr.disable()


s = StringIO.StringIO()
ps = pstats.Stats(pr, stream=s).sort_stats("cumulative")
ps.print_stats()
print(s.getvalue())

Here is a snippet of the report:

         1000130 function calls in 2.448 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    2.438    2.438 /usr/local/lib/python2.7/dist-packages/jinja2/environment.py:974(render)
        1    0.122    0.122    2.438    2.438 {method 'join' of 'unicode' objects}
  1000104    0.315    0.000    2.317    0.000 <template>:5(root)
        1    0.000    0.000    2.002    2.002 /usr/local/lib/python2.7/dist-packages/jinja2/runtime.py:169(call)
        1    0.000    0.000    2.002    2.002 profilej.py:10(slow)
        1    2.002    2.002    2.002    2.002 {time.sleep}
        2    0.010    0.005    0.010    0.005 {range}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/dist-packages/jinja2/environment.py:1015(new_context)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/dist-packages/jinja2/runtime.py:55(new_context)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/dist-packages/jinja2/runtime.py:115(__init__)
        3    0.000    0.000    0.000    0.000 {hasattr}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/dist-packages/jinja2/_compat.py:59(<lambda>)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/dist-packages/jinja2/nodes.py:81(__init__)
        3    0.000    0.000    0.000    0.000 {getattr}
        3    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/dist-packages/jinja2/runtime.py:149(resolve)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/dist-packages/jinja2/runtime.py:126(<genexpr>)
        1    0.000    0.000    0.000    0.000 {callable}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {method 'iteritems' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 {isinstance}

As I said I don't have much experience interpreting the output of profilers but I think in this example you can see the program spends a little over 2 seconds on time.sleep as expected, which is called by slow(). The rest of the of the time is taken up by join. I assume that is how Jinja2 processes my two for loops.

Adapting this example into a flask application shouldn't be too hard, just add the profiling bit around the template generation step and write the report to a file. Perhaps you could even extract your templates from the web application and profile them outside of flask.

I hope this is helpful.

Answer 2

For a multi-threaded application like a running Flask server I find that the usual Python profiling tools aren't that great.

I have had good results with yappi which was designed for multithreaded apps. It's pretty straightforward:

import yappi
yappi.start()

   [.. do stuff ..]

yappi.stop()
yappi.convert2pstats(yappi.get_func_stats()).dump_stats('myfile.pstats')

That saves profile data in a pstats compatible file so you can inspect it interactively in python:

>>> import pstats 
>>> s = pstats.Stats('myfile.pstats')
>>> s.strip_dirs().sort_stats('cumtime').print_stats()

If you want to be clever you can put the start() bit and the stop() bit in Flask handlers so you can hit a URL to start profiling, drive your app, then hit a different URL to stop profiling and write out the stats file.