Poor performance in Django 1.11 after template-based widget rendering

[timgraham]

As reported in Django's Trac ticket #27774, enabling the "Templates" panel on a page that does a lot of template-widget rendering (#15667) results in unacceptably slow page load. I'm not sure what an appropriate resolution might be. A possibility could be to have the debug toolbar ignore analysis for widget rendering.

[chenull]

Cross posting my screenshots

Django 1.10

Django 1.11a1

Django 2.00-dev

[matthiask]

I should probably quickly roll a new release, so that improvements already in master aren't blocked by this.

[kezabelle]

If I had to hazard a guess, I'd assume it were the collection & walking of contexts for every template render that would cause the problem, rather than the firing & recording of signals for every template render.
I think SHOW_TEMPLATE_CONTEXT only affects whether or not they're shown in the expanded panel, right? The data is still collected? If so, perhaps it could be altered to affect both; or there could be a threshold where after N context collections it'd be forced to stop collecting them to avoid this pathological case.

[aaugustin]

@matthiask I don't remember if you have adequete permissions to make releases, please ping me if you need anything. Generally speaking we could release more often ;-) By all means do it if you have time.

[salexkidd]

I have same problem. if use django-countries, got a +500 time rendering (Templates Tab)

[kradem]

Hi everybody!

I just upgraded my project to Django 1.11 and now my pretty simple page with two selects counts more than 100K lines of source.

It goes in some kind of loop where two description terms alternate (I'm showing just the first of those selects):

Virtualenvs

<dt><strong><a class="remoteCall toggleTemplate" href="/__debug__/template_source/?template=django/forms/widgets/attrs.html&template_origin=/home/kradem/.virtualenvs/project/lib/python3.5/site-packages/django/forms/templates/django/forms/widgets/attrs.html">django/forms/widgets/attrs.html</a></strong></dt>
 	<dd><samp>/home/kradem/.virtualenvs/project/lib/python3.5/site-packages/django/forms/templates/django/forms/widgets/attrs.html</samp></dd>

Project code

<dt><strong><a class="remoteCall toggleTemplate" href="/__debug__/template_source/?template=django/forms/widgets/select_option.html&template_origin=/home/kradem/dev/project/project/templates/django/forms/widgets/select_option.html">django/forms/widgets/select_option.html</a></strong></dt>
	<dd><samp>/home/kradem/dev/project/project/templates/django/forms/widgets/select_option.html</samp></dd>

Description list's description

Description for those terms is the same:

<dd>
	<div class="djTemplateShowContextDiv"><a class="djTemplateShowContext"><span class="toggleArrow">&#x25B6;</span> Toggle context</a></div>
	<div class="djTemplateHideContextDiv djdt-hidden"><code>{&#39;False&#39;: False, &#39;None&#39;: None, &#39;True&#39;: True}
{&#39;widget&#39;: {&#39;attrs&#39;: {&#39;id&#39;: &#39;id_language&#39;},
        &#39;is_hidden&#39;: False,
        &#39;name&#39;: &#39;language&#39;,
        &#39;optgroups&#39;: [(None,
                       [{&#39;attrs&#39;: {},                           
    ...
    ...
    &#39;template_name&#39;: &#39;django/forms/widgets/select_option.html&#39;,
    &#39;type&#39;: &#39;select&#39;,
    &#39;value&#39;: &#39;sl&#39;}}
{}</code></div>
</dd>   

---

Best regards!

[peterfarrell]

Seeing similarly extremely poor performance on Django 1.11 with the debug toolbar's TemplatesPanel enabled. Seeing response times of:

• ~300ms on Django 1.10.7
• 300+ seconds on Django 1.11 (honestly I gave up trying to load the page)

The current workaround we're using is to disable the TemplatesPanel in your settings.py. This returns performance back to pre-Django 1.11 levels:

DEBUG_TOOLBAR_CONFIG = {
    # Add in this line to disable the panel
    'DISABLE_PANELS': {
        'debug_toolbar.panels.templates.TemplatesPanel',
        'debug_toolbar.panels.redirects.RedirectsPanel',
    },
}

I can only assume it has to do with the template based widget rendering that is new in Django 1.11?

Edit: Updated to include the RedirectsPanel since that is disabled by default.

[Gagaro]

Please note that the RedirectsPanel is disabled by default (http://django-debug-toolbar.readthedocs.io/en/stable/configuration.html#toolbar-options), so to disable the TemplatesPanel you should actually do:

DEBUG_TOOLBAR_CONFIG = {
    # Add in this line to disable the panel
    'DISABLE_PANELS': {
        'debug_toolbar.panels.redirects.RedirectsPanel',
        'debug_toolbar.panels.templates.TemplatesPanel'
    },
}

[cnobile2012]

I have noticed this issue as well, ever since I upgraded to Django 1.11 when the templates tool is on some of my admin pages never load. A python process takes 100% of the CPU and the only way to stop it is to bounce the runserver.

[ediazpacheco]

Same here. Load time goes from 150ms to several seconds with TemplatesPanel enabled. With django 1.10 it is ok.

[kezabelle]

Having done a little spelunking, it's absolutely to do with TemplatesPanel._store_template_info.

Given a brand new django-admin startproject ... under 1.11, after inserting 200 Groups, and 1 superuser, trying to render the change form in the admin for that user takes about 180 seconds for me locally (obviously YMMV).

During that rendering, 497 templates are collected according to the panel. Most of those are select.html, attrs.html and select_option.html.
Using a couple of globals to track iterations inside _store_template_info it looks like:

• the method is called 497 times (as you'd expect, it mirrors the number of templates reported by the panel output)
• for my output, there are 3069 layers (a layer being a single dict from a Context, itself being composed of multiple dicts)
• a total of 5825 individual keys are iterated over.

The expensive part of all of this is calling pformat ... specifically, if I change the first call to pformat (inside the hot inner loop) to call force_text instead, and leave the second pformat call to do actual formatting, the render time decreases from 180s to 102s~. If I remove both pformat calls and instead just force_text both times, the output isn't nice - each layer is on one line - but it renders in 2(!) seconds.
Because each widget is getting a potentially massive datastructure in its context (for example, the optgroups of select_option contains a list of dictionaries representing every individual option), and must pformat that where previously it never encountered them, it is causing a lot of slowdown just to prettify the data.

There are 2 ideas I have for solving this:

1. Change expanding the context to be an AJAX call, as viewing the template source does, and do the pformat for the individual context there.
2. Cache the temp_layer data into a dictionary, and only apply new pformats as necessary. A brief experiment with doing this seems to work for me in my single test case, and reduces the execution time back down to 3 seconds. I may be able to provide a PR for consideration if this approach "works" (passes tests). It also seems to use less resident memory, though I make no guarantees of that ;)
3. Additionally, perhaps consider changing so that _store_template_info doesn't do anything if SHOW_TEMPLATE_CONTEXT is False?

[goblinJoel]

As someone else who's experiencing the issue, I'm cheering @kezabelle on! Hoping to see a fix soon, as our next release includes an upgrade to Django 1.11, and the templates panel is the one we use most frequently on our content/design staging site.

[matthiask]

@goblinJoel if you could help test this PR locally that would be helpful & awesome!

[goblinJoel]

@matthiask Didn't get a chance to test it yesterday, but I'm excited to see it was merged! Thanks for the fix, @kezabelle !

[goblinJoel]

For what it's worth, I've cloned master and am testing it locally now. A page that took 186s locally and rendered 1,147 templates now takes 8.5s and renders 1140 templates. Almost all of these are widgets (there's a country selector that is responsible for most of those). Chrome's network pane does show the document response's size as 237 MB (!!!), which seems high. This does appear to be the size of the response itself (not just after JS runs to populate toolbar things), as the Django local server shows the following entry:
[02/May/2017 09:59:37] "GET /my/test/url/ HTTP/1.1" 200 248339897

On refresh, the same page took 4s and renders 566 templates (and the document is 119 MB). Previously, it was 45s and 566. In this case, refresh would be unusual, but it's still worth noting.

In Firefox, I get similar results: 7s to render 1140 and download 237 MB. On refresh, 3s to render 566 and download 119 MB. (The speed difference might be because Chrome is on an Ubuntu VM, and FF is on the host Windows machine.)

This is an order of magnitude faster! I'm concerned that the download size will be a problem on our shared dev and staging environments, but at least the response itself is being created much, much faster. Nevertheless, this is definitely a huge improvement, as it makes pages with select widgets usable on local with the templates panel enabled.

Setting 'SHOW_TEMPLATE_CONTEXT': False improves things dramatically. Chrome gets 1.4s to render 1140 and download 580 KB. Refresh speeds things up to 0.8s, but doesn't change the number of templates rendered or the download size for some reason. Unfortunately, we often need to see the template context, so turning that off isn't an option in our use case. But if it is in yours, it seems to make another huge difference!

Disabling the template panel changes things to 0.9s, with 0.3s on refresh. Page size is down to 250-350 KB.

Hope those timings are a useful sampling for any further improvements! Thanks for the fix! Looking forward to a release.

[goblinJoel]

Note: My tests above were on a page that's pretty much a worst case scenario. On pages with few or no widgets, it loads snappily, and even an admin page with a lot of widgets (1177 total templates rendered!) loaded in 3s with 48 MB response size (still big, but not as crazy). [Edit: Switched back to djdt 1.7, and it went up to 20s load, same template count and response size.] I suspect this is because the widget contexts aren't as huge. On my worst-case sample, most of the widget templates were for a country selector, so their context dicts for widget.optgroups and group_choices (inherited from select.html via {% include %}) were enormous, and there were multiple templates rendered for every country option, making things scale exponentially.

[matthiask]

I'm thinking a bit about introducing a new setting that would suppress widget-related templates in the templates panel... not sure whether that makes sense yet!

[goblinJoel]

I think there are two remaining issues:

1. Usability. The template panel becomes less useful if you have to wade through hundreds or even thousands of widget templates to find the one non-widget template you're looking for. (On the other hand, not being able to see what widget templates are rendering at all could cause its own problems.)
2. Performance. The merged fix improves this dramatically, so the remaining issue is probably the large response sizes (potentially >100 MB) that can happen when template context is shown. [EDIT: Wow! I just tried a user change page, as mentioned in the PR, and for me, after a long time, my local server gives a 2,159,708,387-byte response, and the page fails to load. That's just over 2 GB! I have 24 group options, a probably-high number of permission options, and a lot of country options (in an inline for an address model). If I turn off the template panel, it loads quickly.]

Your suggestion of a setting to suppress widget-related templates might make sense.

Another option (which might overcomplicate things) could be to do something like the SQL panel, where it detects duplicate templates or contexts (I think the merged fix already detects the latter?) and doesn't bother to render them, instead noting by the template path that it was duplicated X times. Perhaps you could click to have it AJAX load them in anyway. (Is that still even possible, once the page has rendered?) This way, you could reduce response size by quite a bit for certain cases.

Alternatively, if it is possible to retrieve template contexts once the page has already rendered, perhaps contexts don't load until you click on them.

Yet another option could be to just suppress repetitive templates related to select widgets. In my case, that's django/forms/widgets/select_option.html and django/forms/widgets/attrs.html.

What about allowing a set of filters for templates to exclude from the templates panel? Ex: "django/forms/widgets/*". I don't know how you'd determine that a template is part of a widget, and if you have to hard-code such a filter, it might as well be user-configurable.

[goblinJoel]

As a quick proof of concept, I checked what would happen if we implemented the widget-template-suppression suggestion by changing debug_toolbar.panels.templates.panel.TemplatesPanel._store_template_info():
86 # Skip templates that we are generating through the debug toolbar.
87 if isinstance(template.name, six.string_types):
88 if template.name.startswith('debug_toolbar/'):
89 return
90 if template.name.startswith('django/forms/widgets/'):
91 return

That worked quite well, even with the custom template loader my codebase uses.

I also tried using a list:
90 exclude_templates = [
91 'django/forms/widgets/',
92 'does/not/exist',
93 'admin/widgets/related_widget_wrapper.html'
94 ]
95 for exclude in exclude_templates:
96 if template.name.startswith(exclude):
97 return

This also worked. If that's a solution you like, making it exclude based on a setting definitely seems to solve the problem, albeit with no way to enable/disable client-side.

EDIT: In case it's useful, here's the more minimal list I'm using locally and would probably set it to if you went with a user-configurable list: ['django/forms/widgets/attrs.html', 'django/forms/widgets/input.html', 'django/forms/widgets/select_option.html',]

[kezabelle]

I just tried a user change page, as mentioned in the PR, and for me, after a long time, my local server gives a 2,159,708,387-byte response, and the page fails to load. That's just over 2 GB!

I'll confess, that's not a metric I even considered, and is ... let's say ... unacceptable.

Another option could be to do something like the SQL panel, where it detects duplicate templates or contexts and doesn't bother to render them, instead noting by the template path that it was duplicated X times.

That's an interesting idea, because even in the test page I was using, the sheer number of templates/repetitions was overwhelming to the point of potential uselessness.

Alternatively, if it is possible to retrieve template contexts once the page has already rendered, perhaps contexts don't load until you click on them.

This was something I thought about doing, as one of the other panels does something similar, but I thought you might end up losing context debugging if a number of requests go through that exceeds RESULTS_CACHE_SIZE ... which would also prove useless and frustrating.

In my personal opinion:

• there probably does need to be an TEMPLATE_IGNORE_PATHS (or whatever) option, at the very least as an escape hatch for if nothing ele can be done.
• SHOW_TEMPLATE_CONTEXT should probably also short-circuit the whole context-walking part of the function, rather than just the display of it at render. It won't be a huge boost, but it makes sense to avoid the work we can, given there's now so much more to potentially do.
• Collapsing duplicates is interesting, and worth exploring. Possibly some JS to copy a context from the original node to the duplicate on the client-side would make the most sense, rather than merging templates, so that the template list is still a linear representation? Not sure.

addendum: 'django/forms/widgets/attrs.html' and 'django/forms/widgets/select_option.html' were responsible for a lot of the churn in my testing, too. So at least there's some consistency :)

[goblinJoel]

By the way, I don't think any of this negates @kezabelle 's change, which also definitely improved server-side performance (at least, for me). Thanks!

[matthiask]

When I'm loading the templates panel on a user change page in a current project of mine I'm getting a 5MB response which is perfectly acceptable. 2GB is obviously much too much, but I'm almost three orders of magnitude below that.

The ideas mentioned are definitely interesting, esp. deduplicating content, lazy loading etc. However, it seems to me that implementing those solutions would me much more complicated than either skipping some templates completely (as @goblinJoel tried out already) or maybe just skipping context rendering for selected templates with a short description why this happened. Something like IGNORE_TEMPLATE_CONTEXT = [... list of regex patterns ...]

Of course that's not the most beautiful solution, but maybe it's more feasible given time constraints.

[goblinJoel]

I think doing a simple solution like a list of either regex or startswith patterns to ignore works. The other ideas may be worth looking into for the future, but, since 1.11 is already out, doing something quick and easier to test is probably worth it. I'd personally prefer having it ignore the templates entirely, not just context, so that it solves the "flood of templates" issue as well, but I could go either way.

EDIT: With a fix that ignores attrs.html, input.hml, and select_option.html, I get a much more acceptable 3.1MB response, similar to matthiask's.

---

Boring Speculation:

I'm not sure why I was getting 237MB on one page and 2GB on another. I think part of it is that both those pages have country fields, which on our site means literally hundreds of options. The size seems to balloon exponentially based on the number of options you have, as the full context for all options shows up on each option. Pages with fewer widgets (or at least, smaller multi-option widgets) didn't have the problem nearly as bad.

I think the huge size on our user change page is because ours has a groups select with 24 options, permissions with 922 options (we have a lot of models), 2 address country with 250 options each (not sure why we have 2), and a handful of much smaller ones. Quick math, assuming time for a widget scales by the number of options squared, gives a factor 975,660 (plus smaller widgets and constant factors) for my user change page. The other page I was looking at had a single select with 254 options for a factor of 64,516.

So, I'd expect the one page to be about 15x as big as the other. The actual was 2,060MB vs 237MB, so it was ~8.7x as big. For users in general, I think anyone with a lot of models would encounter large response sizes on their user change page, because of the huge amount of possible permissions that entails.

[matthiask]

Proposed implementation: #942

Feedback is very welcome!

[timb07]

This looks like a sensible solution. Without the fix in #942, it took my browser about 90 seconds to render the Templates panel for one admin page. With the fix, it was less than a second.

Exposing this as a configuration option allows it to be disabled if necessary, so I don't see any downside to it.

[matthiask]

Thanks to all of you. I think we can close this issue. I'll make a new release soon.

[gabn88]

Just wondering, does the latest github master include the fix? Because then it is still slow for me...

[tonysyu]

Yes, it should. I upgraded to django_debug_toolbar == 1.8 and that resolved the issue on my system. I have no idea how it compares to previous performance, but on Django 1.11 and django-debug-toolbar 1.7, I had one page that completely failed to load, but upgrading resolved the issue.

[interDist]

I’m having the latest available debug_toolbar version running on Django 1.11.5, and forms (especially in Admin) are painfully slow. Some load after 3 mins, some never load, some cause memory corruption and server crash.

I collected statistics in this comment: #943 (comment).

[goblinJoel]

@interDist Try adding 'SKIP_TEMPLATE_PREFIXES': ('django/forms/widgets/', 'admin/widgets/') to your DEBUG_TOOLBAR_CONFIG explicitly. Does that change anything? In your linked comment, you mentioned that most of the templates in the toolbar were from django/forms/widgets, which makes me think the default value for that key is not being used.

[interDist]

@goblinJoel That should be the default configuration according to https://django-debug-toolbar.readthedocs.io/en/stable/configuration.html#panel-options, but even when I specify it explicitly, no, it does not help even a bit. Only disabling the TemplatesPanel completely helps.

[goblinJoel]

Hm. If you're certain you're on toolbar v1.8, it sounds like it's ignoring that setting. In the templates panel, you should not be seeing any that start with those prefixes at all (though I believe they still count toward the total rendered count at the top). I'm not sure how to help from there, but someone else may know more.

Meanwhile, I guess confirm that you have the right versions in the toolbar's versions panel (I'm using 1.11.6 and toolbar 1.8 with python 3.5.2, and those work fine) and output your debug toolbar conf on an actual (debug-only) page to verify that the server is definitely reading the settings you've set. Try messing with the setting to see if any values have an effect on which templates show in the panel.

[israel-tk]

I just spent 2 hours today banging my head about what was wrong with my code due to this issue. :(

[goblinJoel]

Were you able to resolve the issue, @israel-tk ? If not, what issue in particular are you experiencing?

Does anyone know how template paths work on Windows? It just occurred to me that if they use backslashes, the default skip prefixes wouldn't catch them.

[israel-tk]

@goblinJoel I have a form with a dropdown select field with ~200 options. With the TemplatesPanel activated it takes too long to render the view, I closed the browser after one-two minutes. Without the TemplatesPanel activated it works perfectly well.

I'm using django toolbar 1.6 - I guess that upgrading might help here as well. Right?

[matthiask]

Yes, the relevant fix is only available in django-debug-toolbar 1.8 and better.

[israel-tk]

Upgraded to 1.9.1 and it now works perfect, thanks! And sorry for disturbing.