Howdy fellow Djangonauts,
I recently ran into a performance problem that was new to me. It stemmed from using the date template filter thousands of time in a for loop within a template. On our production machine, it took 8s to render the template via render_to_string.
My question is, has anyone else ever ran into this and/or is this a known issue? It appears that the culprit is django.utils.dateformat.format.
The effective code is:
{% for value in values %}
<tr>
<td>
{{ value|date:"DATE_FORMAT" }}
<br />{{ value|time:"TIME_FORMAT" }}
</td>
</tr>
{% endfor %}
I just benchmarked those filters and they are very fast - about 10-20 microseconds per iteration, with the default format, Python 3.9, and Django 3.1:
$ python manage.py shell
Python 3.9.0 (default, Oct 10 2020, 10:28:14)
Type 'copyright', 'credits' or 'license' for more information
IPython 7.18.1 -- An enhanced Interactive Python. Type '?' for help.
In [1]: from django.template.defaultfilters import date
In [2]: import datetime as dt
In [3]: now = dt.datetime.utcnow()
In [4]: date(now)
Out[4]: 'Oct. 19, 2020'
In [5]: %timeit date(now)
20.3 µs ± 252 ns per loop (mean ± std. dev. of 7 runs, 10000 loops each)
In [6]: from django.template.defaultfilters import time
In [7]: time(now)
Out[7]: '4:49 p.m.'
In [8]: %timeit time(now)
13.6 µs ± 318 ns per loop (mean ± std. dev. of 7 runs, 100000 loops each)
I get the same results if I provide "DATE_FORMAT" / "TIME_FORMAT" as arguments, although my settings don’t contain them.
With this speed, even for thousands of objects you shouldn’t be reaching 8 seconds - 1000 iterations at 20 microseconds totals just 0.02 seconds.
Can you try using %timeit on a Template.render() with that chunk to show the slowness? And then run a profiler like py-spy or austin to spot the slow parts? Perhaps there’s something about t
1 Like
Good call. It doesn’t appear to be related to the template filter. Seems like a context issue.
Using the following template:
<div>
{% for value, others in values %}
<p>{{ value }}</p>
<ol>
{% for other in others %}
<li>{{ other|date:"Y/n/j g:i A" }}</li>
{% endfor %}
</ol>
{% endfor %}
</div>
And the following context:
context = {"values": [(i, [now - timedelta(minutes=j) for j in range(4)]) for i in range(10000)]}
Produces
In [49]: %timeit x = template.render(context, None)
3.64 s ± 40.9 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)
If I remove the date template filter for {{ other }} and use a more basic context:
context = {"values": [(i, list(range(4))) for i in range(10000)]}
Produces
In [43]: %timeit x = template.render(context, None)
957 ms ± 6.23 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)
The py-spy’s top sorted by Own %.
Total Samples 383
GIL: 0.00%, Active: 100.00%, Threads: 1
%Own %Total OwnTime TotalTime Function (filename:line)
11.00% 17.00% 0.250s 0.310s format (django/utils/dateformat.py:43)
6.00% 6.00% 0.140s 0.140s __getattr__ (asgiref/local.py:107)
5.00% 6.00% 0.120s 0.130s format (django/utils/dateformat.py:34)
4.00% 4.00% 0.040s 0.040s wrapper (django/utils/functional.py:220)
4.00% 4.00% 0.050s 0.050s _get_context_id (asgiref/local.py:72)
4.00% 5.00% 0.130s 0.180s _get_context_id (asgiref/local.py:51)
3.00% 3.00% 0.030s 0.030s _subx (re.py:327)
3.00% 5.00% 0.040s 0.070s get_current_task (asgiref/sync.py:351)
2.00% 18.00% 0.020s 0.470s __text_cast (django/utils/functional.py:140)
2.00% 20.00% 0.020s 0.350s get_language (django/utils/translation/trans_real.py:303)
2.00% 2.00% 0.020s 0.020s render (django/template/defaulttags.py:204)
2.00% 2.00% 0.020s 0.020s inner (django/utils/functional.py:241)
2.00% 72.00% 0.020s 1.46s date_format (django/utils/formats.py:152)
2.00% 2.00% 0.020s 0.020s gettext (django/utils/translation/trans_real.py:352)
2.00% 22.00% 0.030s 0.380s get_language (django/utils/translation/__init__.py:254)
2.00% 2.00% 0.030s 0.030s current_task (asyncio/tasks.py:37)
2.00% 2.00% 0.020s 0.020s render (django/template/defaulttags.py:210)
2.00% 2.00% 0.020s 0.020s __getitem__ (django/template/context.py:80)
I’ve also included a screenshot of the speedscope results. I don’t feel comfortable uploading the raw file given I’m unsure of what’s all included in it. Generally, I don’t see any quick wins. It looks like I need to rework the application to render this page piecemeal.
There’s a lot of repetitive calculations in that nested comprehension.
[now - timedelta(minutes=j) for j in range(4)]
You’re repeating this 10,000 times to recalculate the same set of values
Even your simplified form is creating a different list for each iteration - is that really necessary? (If not, I’m sure there’s some benefit to be gained by reusing the same list)
What if you were to try:
delta_list = [now - timedelta(minutes=j) for j in range(4)]
context = {"values": [(i, delta_list) for i in range(10000)]}
On my laptop:
In [66]: %timeit context = {"values": [(i, [now - timedelta(minutes=j) for j in range(4)]) for i in range(10000)]}
45.5 ms ± 131 µs per loop (mean ± std. dev. of 7 runs, 10 loops each)
vs
In [67]: delta_list = [now-timedelta(minutes=j) for j in range(4)]
...
In [69]: %timeit context = {"values": [(i, delta_list) for i in range(10000)]}
740 µs ± 2.45 µs per loop (mean ± std. dev. of 7 runs, 1000 loops each)
about 1/50th of the time.
Ken
Ah, I wrote the sample data code wrong. I meant to have different datetime values for each instance in the list.
Edit, no I think what I have works well enough for the example. It’s obviously not great, but it works for its purpose.
We’re reworking the page. Finally took a look at the size of the response and it’s at 15MB. Yikes.
Yea… that’s never good. You’re going to encounter all other sorts of delays as well regarding rendering speeds in the browser.
(I’ve got a page I’m working on now that is rendering about 8 MB - time to paginate…)
Yup! I started in on this from, “why’s this page timing out?”. Finally asked, what does it look like with just little enough data to not time out?
