Merge pull request #17 from PetrDlouhy/trace_nodes

Break temlate parsing timeline by separate nodes

Author: node13h

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):
@@ -19,6 +54,7 @@ class TemplateProfilerPanel(Panel):
     '''
 
     template = 'template_profiler_panel/template.html'
+    scripts = ["static/js/template_profiler.js"]
 
     def __init__(self, *args, **kwargs):
         self.colors = {}
@@ -49,6 +85,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 +102,34 @@ def render_wrapper(wrapped, instance, args, kwargs):
                     break
                 stack_depth += 1
 
+            timeline = []
+            if hasattr(instance, 'nodelist'):
+                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 +148,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 +174,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 +189,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 +200,43 @@ 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'] = []
+        max_level = 0
+        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:
+                position = False
+            level = time_item['level'] if 'level' in time_item else 0
+            if level > max_level:
+                max_level = level
+            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': level,
+            })
+        result['max_level'] = max_level
+
         return result
 
     def process_request(self, request):
@@ -165,7 +259,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)
 

template_profiler_panel/static/js/template_profiler.js

@@ -0,0 +1,6 @@
+
+$(".timeline_item").mouseover(function() {
+   $(this).css("border", "red 0.1px solid");
+}).mouseout(function() {
+   $(this).css("border", "none");
+});

template_profiler_panel/templates/template_profiler_panel/template.html

@@ -3,13 +3,15 @@ <h4>{{ templates|length }} {% trans 'calls to Template.render()' %}</h4>
 <div>
   <table>
     <colgroup>
+      <col style="width:1%" />
       <col style="width:5%" />
-      <col style="width:30%" />
+      <col style="width:10%" />
       <col style="width:60%" />
       <col style="width:5%" />
     </colgroup>
     <thead>
       <tr>
+        <th></th>
         <th>{% trans 'Stack Level' %}</th>
         <th>{% trans 'Template Name' %}</th>
         <th>{% trans 'Timeline' %}</th>
@@ -18,20 +20,52 @@ <h4>{{ templates|length }} {% trans 'calls to Template.render()' %}</h4>
     </thead>
     <tbody>
       {% for template in templates %}
-      <tr class="{% cycle 'djDebugOdd' 'djDebugEven' %}">
+      <tr class="{% cycle 'djDebugOdd' 'djDebugEven' %}" id="profileMain_{{ forloop.counter }}">
+        <td class="djdt-toggle">
+           <button type="button" class="djToggleSwitch" data-toggle-name="profileMain" data-toggle-id="{{ forloop.counter }}">+</button>
+        </td>
         <td>
           <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 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>
         </td>
         <td>{{ template.time|floatformat }}</td>
       </tr>
+      <tr class="djToggleDetails_{{ forloop.counter }} djUnselected" id="sqlDetails_{{ forloop.counter }}">
+         <td></td>
+         <td></td>
+         <td></td>
+         <td>
+            <div style="height: calc({{ template.max_level|add:1 }}px * 18); position:relative;" class="timeline_toggle_{{ forloop.counter }} djToggleDetails_{{ forloop.counter }} djSelected" id="sqlDetails_{{ 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 }}
+                  "
+                  class="timeline_item"
+                  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;
+                  opacity: 0.9;
+                  ">&nbsp;</span>
+            {% endfor %}
+            </div>
+         </td>
+         <td></td>
+      </tr>
       {% endfor %}
     </tbody>
   </table>

template_profiler_panel/templatetags/__init__.py

@@ -0,0 +1,25 @@
+from django import template
+from django.template.base import Node
+
+
+register = template.Library()
+
+
+@register.tag
+def profile(parser, tags):
+    nodelist = parser.parse(('endprofile',))
+    parser.delete_first_token()
+    return ProfileNode(nodelist, tags)
+
+
+class ProfileNode(Node):
+    def __init__(self, nodelist, tags):
+        self.nodelist = nodelist
+        self.block_name = tags.contents.split(' ')[1].strip("'")
+
+    def __str__(self):
+        return f"Profile {self.block_name}"
+
+    def render(self, context):
+        result = self.nodelist.render(context)
+        return result