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?