17

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?

akai
  • 2,498
  • 4
  • 24
  • 46
andy boot
  • 11,355
  • 3
  • 53
  • 66
  • 1
    @akai: I don't know flask but it looks like python. [*This should work.*](http://stackoverflow.com/a/4299378/23771) – Mike Dunlavey Oct 29 '16 at 15:40
  • 1
    I think in the profiler in the flask-debugtoolbar you may see all the methods invoked. If you filter manually those having jinja2 in front (i.e. ) you may have an estimate of the rendering time. – Alexey Smirnov Oct 30 '16 at 12:57
  • possibly a related question? http://stackoverflow.com/questions/618827/optimizing-jinja2-environment-creation – intrepidhero Nov 01 '16 at 17:43
  • @MikeDunlavey The answer is very interesting but it seems it doesn't help in this case. I tried it out but the stacktrace somehow reports the process is stopped at a mere html line - that is, no-python line in the jinja2 template - and some jinja2 internal code follows, without showing which template line was being rendered before the interruption. – akai Nov 02 '16 at 14:59
  • @AlexeySmirnov Although that doesn't work if the slow function isn't from jinja2 (e.g. from flask), I feel that looking through the profiling result is the "best" way anyway, maybe... – akai Nov 02 '16 at 15:11
  • @intrepidhero As long as I know, flask compiles jinja2 templates only once if it's not updated (and the OP is interested in the use case in flask, so am I). – akai Nov 02 '16 at 15:15

3 Answers3

5

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.

intrepidhero
  • 701
  • 7
  • 10
1

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.

Bill Gribble
  • 1,797
  • 12
  • 15
  • I tried this, too, but I found this doesn't help any more than flask-debugtoolbar does (at least in terms of jinja2 rendering). – akai Nov 05 '16 at 05:39
0

If anyone needs a quick "hacky" way to profile certain Jinja snippet render times, I found an easy way of doing it.

Add this to the main app file:

app.jinja_env.globals.update(now=datetime.datetime.now)

Add this around the snippet you want to time:

{% set rendertime = now() %}

{% for x in test_list %}
   {{... do stuff }}
{% endfor %}

<span>Render Time: {{now()-rendertime}}</span>
Andrew McDonald
  • 1
  • 1