add trace of rendering template nodes

PetrDlouhy · PetrDlouhy · commit dbb17906b68d · 2021-01-14T20:25:26.000+01:00
diff --git a/template_profiler_panel/panels/template.py b/template_profiler_panel/panels/template.py
@@ -3,14 +3,49 @@
 from time import time
 
 import wrapt
-from django.dispatch import Signal
-from django.utils.translation import ugettext_lazy as _
-
 from debug_toolbar.panels import Panel
 from debug_toolbar.panels.sql.utils import contrasting_color_generator
+from django.dispatch import Signal
+from django.utils.translation import ugettext_lazy as _
 
-
-template_rendered = Signal(providing_args=['instance', 'start', 'end', 'level'])
+template_rendered = Signal(providing_args=[
+    'instance', 'start', 'end', 'level', 'processing_timeline',
+])
+
+
+node_element_colors = {}
+
+
+def get_nodelist_timeline(nodelist, level):
+    timeline = []
+    for node in nodelist:
+        timeline += get_node_timeline(node, level)
+    return timeline
+
+
+def get_node_timeline(node, level):
+    """
+    Get timeline for node and it's children
+    """
+    timeline = []
+    child_nodelists = getattr(node, "child_nodelists", None)
+    if child_nodelists:
+        for child_nodelist_str in child_nodelists:
+            child_nodelist = getattr(node, child_nodelist_str, None)
+            if child_nodelist:
+                timeline += get_nodelist_timeline(child_nodelist, level + 1)
+
+    if hasattr(node, "_node_end"):
+        timeline.append(
+            {
+                "node": node,
+                "name": node,
+                "start": node._node_start,
+                "end": node._node_end,
+                "level": level,
+            },
+        )
+    return timeline
 
 
 class TemplateProfilerPanel(Panel):
@@ -49,6 +84,9 @@ def monkey_patch_template_classes(cls):
         else:
             template_classes.append(Jinja2Template)
 
+        from django.template import Node as DjangoNode
+        node_classes = [DjangoNode]
+
         @wrapt.decorator
         def render_wrapper(wrapped, instance, args, kwargs):
             start = time()
@@ -63,18 +101,32 @@ def render_wrapper(wrapped, instance, args, kwargs):
                     break
                 stack_depth += 1
 
+            timeline = get_nodelist_timeline(instance.nodelist, 0)
+
             template_rendered.send(
                 sender=instance.__class__,
                 instance=instance,
                 start=start,
                 end=end,
+                processing_timeline=timeline,
                 level=stack_depth,
             )
             return result
 
         for template_class in template_classes:
             template_class.render = render_wrapper(template_class.render)
 
+        @wrapt.decorator
+        def render_node_wrapper(wrapped, instance, args, kwargs):
+            instance._node_start = time()
+            result = wrapped(*args, **kwargs)
+            instance._node_end = time()
+            return result
+
+        for node_class in node_classes:
+            node_class.render_annotated = render_node_wrapper(
+                node_class.render_annotated)
+
         cls.have_monkey_patched_template_classes = True
 
     @property
@@ -93,7 +145,8 @@ def title(self):
     def _get_color(self, level):
         return self.colors.setdefault(level, next(self.color_generator))
 
-    def record(self, instance, start, end, level, **kwargs):
+    def record(self, instance, start, end, level,
+               processing_timeline, **kwargs):
         if not self.enabled:
             return
 
@@ -118,6 +171,7 @@ def record(self, instance, start, end, level, **kwargs):
             'end': end,
             'time': (end - start) * 1000.0,
             'level': level,
+            'processing_timeline': processing_timeline,
             'name': template_name,
             'color': color,
         })
@@ -132,7 +186,7 @@ def _calc_p(self, part, whole):
         # return the percentage of part or 100% if whole is zero
         return (part / whole) * 100.0 if whole else 100.0
 
-    def _calc_timeline(self, start, end):
+    def _calc_timeline(self, start, end, processing_timeline):
         result = {}
         result['offset_p'] = self._calc_p(
             start - self.t_min, self.t_max - self.t_min)
@@ -143,6 +197,38 @@ def _calc_timeline(self, start, end):
         result['rel_duration_p'] = self._calc_p(
             result['duration_p'], 100 - result['offset_p'])
 
+        result['relative_start'] = (start - self.t_min) * 1000.0
+        result['relative_end'] = (end - self.t_min) * 1000.0
+
+        result['processing_timeline'] = []
+        for time_item in processing_timeline:
+            if 'node' in time_item:
+                class_name = time_item['node'].__class__.__name__
+            else:
+                class_name = time_item['type']
+            if class_name not in node_element_colors:
+                node_element_colors[class_name] = next(self.color_generator)
+            bg_color = node_element_colors[class_name]
+            if 'node' in time_item:
+                position = time_item['node'].token.position
+            else:
+                False
+            result['processing_timeline'].append({
+                'name': time_item['name'],
+                'position': position,
+                'relative_start': (time_item['start'] - self.t_min) * 1000.0,
+                'relative_end': (time_item['end'] - self.t_min) * 1000.0,
+                'duration': (time_item['end'] - time_item['start']) * 1000.0,
+                'rel_duration_p': self._calc_p(
+                    time_item['end'] - time_item['start'],
+                    self.t_max - self.t_min),
+                'offset_p': self._calc_p(
+                    time_item['start']-self.t_min,
+                    self.t_max - self.t_min),
+                'bg_color': bg_color,
+                'level': time_item['level'] if 'level' in time_item else 0,
+            })
+
         return result
 
     def process_request(self, request):
@@ -165,7 +251,9 @@ def process_request(self, request):
         # Calc timelines
         for template in self.templates:
             template.update(
-                self._calc_timeline(template['start'], template['end']))
+                self._calc_timeline(
+                    template['start'], template['end'],
+                    template['processing_timeline']))
 
         self.total = len(self.templates)
 
diff --git a/template_profiler_panel/templates/template_profiler_panel/template.html b/template_profiler_panel/templates/template_profiler_panel/template.html
@@ -4,14 +4,16 @@ <h4>{{ templates|length }} {% trans 'calls to Template.render()' %}</h4>
   <table>
     <colgroup>
       <col style="width:5%" />
-      <col style="width:30%" />
+      <col style="width:10%" />
+      <col style="width:1%" />
       <col style="width:60%" />
       <col style="width:5%" />
     </colgroup>
     <thead>
       <tr>
         <th>{% trans 'Stack Level' %}</th>
         <th>{% trans 'Template Name' %}</th>
+        <th>{% trans 'Trace' %}</th>
         <th>{% trans 'Timeline' %}</th>
         <th>{% trans 'Time (ms)' %}</th>
       </tr>
@@ -23,10 +25,36 @@ <h4>{{ templates|length }} {% trans 'calls to Template.render()' %}</h4>
           <div style="background-color: {{ template.color.bg }}; color: {{ template.color.text }}; width: {{ template.level }}px; margin-right: 4px; padding-left: 2px;">{{ template.level }}</div>
         </td>
         <td>{{ template.name }}</td>
+        <td>
+           <a href="javascript:$('.timeline_toggle_{{ forloop.counter }}').toggle();">
+              <div class="timeline_toggle_{{ forloop.counter }}">&#9658;</div>
+              <div class="timeline_toggle_{{ forloop.counter }}" style="display: none;">&#9660;</div>
+           </a>
+        </td>
         <td class="timeline">
-          <div class="djDebugTimeline">
+          <div class="djDebugTimeline" style="position:relative;">
             <div class="djDebugLineChart" style="margin-left: {{ template.offset_p|stringformat:'f' }}%;">
-              <div title="Start {{ template.start }}" style="min-width: 1px; width: {{ template.rel_duration_p|stringformat:'f' }}%; background-color: {{ template.color.bg }};">&nbsp;</div>
+               <div title="Runtime {{ template.relative_start|floatformat:2 }} - {{ template.relative_end|floatformat:2 }} ms" style="min-width: 1px; width: {{ template.rel_duration_p|stringformat:'f' }}%; background-color: {{ template.color.bg }};">
+                  &nbsp;</div>
+            </div>
+            <div style="height: 200px; position:relative; display: none;" class="timeline_toggle_{{ forloop.counter }}">
+            {% for time_item in template.processing_timeline %}
+               <span title="{{ time_item.name }}
+Runtime {{ time_item.relative_start|floatformat:2 }} - {{ time_item.relative_end|floatformat:2 }} ms
+Duration {{ time_item.duration|floatformat:2  }} ms
+{% if time_item.position %}Lines {{ time_item.position.0 }} - {{ time_item.position.1 }}{% endif %}
+Depth {{ time_item.level|add:1 }}
+                  " style="
+                  min-width: 1px;
+                  margin-left: {{ time_item.offset_p|stringformat:'f' }}%;
+                  width: {{ time_item.rel_duration_p|stringformat:'f' }}%;
+                  background-color: {{ time_item.bg_color }};
+                  top: calc({{ time_item.level }}px * 18);
+                  position: absolute;
+                  {# border: red 0.1px solid; #}
+                  opacity: 0.9;
+                  ">&nbsp;</span>
+            {% endfor %}
             </div>
           </div>
         </td>
