Degraded performance when rendering ChoiceField with lots of options and DEBUG=True

[karyon]

One ChoiceField with 1k options took 6s instead of 0.5s after updating to django 1.11 with DEBUG=True.

apollo13 created a reduced test case:

    import django
    from django.conf import settings
     
    settings.configure(DEBUG=True)
    django.setup()
     
     
    from django.forms import Form, Select, ChoiceField
     
     
    class TestForm(Form):
        test = ChoiceField(widget=Select, choices=map(lambda x: (str(x), str(x)), range(1000)))
     
     
    print(TestForm())

and the following test

strace python3 test.py 2>&1|grep attr|wc
    1001    4004  120120

shows that ​this file is read 1k times. It seems like the caching of the include tag inside loops does not work with nested includes. apollo13 investigated further.

[Florian Apolloner]

The main issue here is that the render context is per template rendering. I'd argue that the resolved templates should stay constant during one rendering cycle so this might be a somewhat sensible fix:

diff --git a/django/template/loader_tags.py b/django/template/loader_tags.py
index d043e5eb52..6050b9f61f 100644
--- a/django/template/loader_tags.py
+++ b/django/template/loader_tags.py
@@ -175,7 +175,7 @@ class IncludeNode(Node):
             if not callable(getattr(template, 'render', None)):
                 # If not, we'll try our cache, and get_template()
                 template_name = template
-                cache = context.render_context.setdefault(self.context_key, {})
+                cache = context.render_context.dicts[0].setdefault(self.context_key, {})
                 template = cache.get(template_name)
                 if template is None:
                     template = context.template.engine.get_template(template_name)

Edit:// Note that RenderContext explains this behavior: ​https://github.com/django/django/blob/325db2a8c3453a56db5e0df0eed37476eb67802d/django/template/context.py#L177-L190 (for better or worse)

[Preston Timmons]

Keeping the resolved templates constant makes sense to me.

[kapil garg]

Can i start working on it ?

[karyon]

i'm not a project member, but yes you probably can.

from a discussion on #django-dev:

20:34:30 - apollo13: this added the initial caching: ​https://github.com/django/django/commit/a391b17ad24bc5f255a3928c23c158c79004c656 […]
20:38:14 - apollo13: first step would be running the tests with my patch applied and then thinking about what that means for ifchanged
20:38:34 - apollo13: especially if you get more creative here: ​https://github.com/django/django/commit/a391b17ad24bc5f255a3928c23c158c79004c656#diff-25712b0bc568d3a2bb139891f294872dR207 and put another include/ifchanged outside the loop
20:39:24 - apollo13: or maybe also adding a second include inside the loop

[kapil garg]

​PR

[Tim Graham]

I think we'd like a test for that, if possible.

[kapil garg]

There are certain problems because of caching.

1. cycle tag does not work in included template in a for loop just like this bug ifchanged bug . The following patch seems to resolve the issue but it raises problem 2.

diff --git a/django/template/defaulttags.py b/django/template/defaulttags.py
index e2be85b..3d6832e 100644
--- a/django/template/defaulttags.py
+++ b/django/template/defaulttags.py
@@ -74,10 +74,11 @@ class CycleNode(Node):
         self.silent = silent
 
     def render(self, context):
-        if self not in context.render_context:
+        state_frame = self._get_context_stack_frame(context)
+        if self not in state_frame:
             # First time the node is rendered in template
-            context.render_context[self] = itertools_cycle(self.cyclevars)
-        cycle_iter = context.render_context[self]
+            state_frame[self] = itertools_cycle(self.cyclevars)
+        cycle_iter = state_frame[self]
         value = next(cycle_iter).resolve(context)
         if self.variable_name:
             context.set_upward(self.variable_name, value)
@@ -89,7 +90,20 @@ class CycleNode(Node):
         """
         Reset the cycle iteration back to the beginning.
         """
-        context.render_context[self] = itertools_cycle(self.cyclevars)
+        state_frame = self._get_context_stack_frame(context)
+        state_frame[self] = itertools_cycle(self.cyclevars)
+
+    def _get_context_stack_frame(self, context):
+        if 'forloop' in context:
+            return context['forloop']
+        else:
+            return context.render_context

2. Nodes will share same state on multiple calls to include same template. Currently i can verify this for Cycle and Ifchanged nodes. The reason is that these nodes use "self" as a dictionary key to store their state and caching prevents generating new nodes on multiple include calls. One solution i can think of to solve this problem is to use "self" as dictionary key for template caching as this will create a new cache for each include node but this will lose the benefit of caching when there are 100 hardcoded include tags instead of being in a forloop.

These issues are related to caching so should we handle these on this ticket or create a new ticket ?

[kapil garg]

This ​PR which introduced caching does not seem to work for nested includes. So the actual caching will happen using patch given by Florian above. Also to resolve the above 2 problems, we need to update CycleNode state location just like ifchanged (patch above) and then we should have separate cache for different include nodes even if they are including the same template as this will force creation of new nodes which use "self" as their state location. (patch below)

diff --git a/django/template/loader_tags.py b/django/template/loader_tags.py
index d043e5eb52..6050b9f61f 100644
--- a/django/template/loader_tags.py
+++ b/django/template/loader_tags.py
@@ -175,7 +175,7 @@ class IncludeNode(Node):
             if not callable(getattr(template, 'render', None)):
                 # If not, we'll try our cache, and get_template()
                 template_name = template
-                cache = context.render_context.setdefault(self.context_key, {})
+                cache = context.render_context.dicts[0].setdefault(self, {})
                 template = cache.get(template_name)
                 if template is None:
                     template = context.template.engine.get_template(template_name)

def test_include(self):
    engine = Engine(loaders=[
        ('django.template.loaders.locmem.Loader', {
            'template': '{% for x in vars %}{% include "include" %}{% include "include" %}{% endfor %}',
            'include': '{% ifchanged %}{{ x }}{% endifchanged %}',
        }),
    ])
    output = engine.render_to_string('template', dict(vars=[1, 1, 2, 2, 3, 3]))
    print(output)

Ideally, the above code should produce "112233" but it produces "123" due to same state being used which can be resolved by applying the above patch ("self" instead of "self.context_key"). Same happens with "cycle" tag i.e. if there is cycle tag instead of ifchanged tag in included template, they will share same state causing undesired behaviour.

The patches in previous comment and in this comment fix all these problems (nested caching and same state) . I can write more tests for these as well.

[kapil garg]

Replying to Tim Graham:

I think we'd like a test for that, if possible.

Tests have been added in the PR for caching and ifchanged state management.

[Tim Graham <timograham@…>]

In 002fe076:

Fixed #27974 -- Kept resolved templates constant during one rendering cycle.

Thanks Florian Apolloner for the initial patch.

[Tim Graham <timograham@…>]

In 76b5165:

[1.11.x] Fixed #27974 -- Kept resolved templates constant during one rendering cycle.

Thanks Florian Apolloner for the initial patch.

Backport of 002fe076225c2aa6e389481b038f55acb6f807d0 from master