Support Server Timing

Adds Server-Timing to response headers. Specification https://www.w3.org/TR/server-timing/

Inspired By https://twitter.com/paul_irish/status/829090506084749312

Author: yurtaev

debug_toolbar/middleware.py

@@ -130,9 +130,32 @@ def process_response(self, request, response):
             # When the toolbar will be inserted for sure, generate the stats.
             for panel in reversed(toolbar.enabled_panels):
                 panel.generate_stats(request, response)
+                panel.generate_server_timing(request, response)
+
+            response = self.generate_server_timing_header(response, toolbar.enabled_panels)
 
             bits[-2] += toolbar.render_toolbar()
             response.content = insert_before.join(bits)
             if response.get('Content-Length', None):
                 response['Content-Length'] = len(response.content)
         return response
+
+    @staticmethod
+    def generate_server_timing_header(response, panels):
+        data = []
+
+        for panel in panels:
+            stats = panel.get_server_timing_stats()
+            if not stats:
+                continue
+
+            for key, record in stats.items():
+                # example: `SQLPanel_sql_time=0; "SQL 0 queries"`
+                data.append('{}_{}={}; "{}"'.format(panel.panel_id,
+                                                    key,
+                                                    record.get('value'),
+                                                    record.get('title')))
+
+        if data:
+            response['Server-Timing'] = ', '.join(data)
+        return response

debug_toolbar/panels/__init__.py

@@ -147,6 +147,21 @@ def get_stats(self):
         """
         return self.toolbar.stats.get(self.panel_id, {})
 
+    def record_server_timing(self, key, title, value):
+        """
+        Store data gathered by the panel. ``stats`` is a :class:`dict`.
+
+        Each call to ``record_stats`` updates the statistics dictionary.
+        """
+        data = {key: dict(title=title, value=value)}
+        self.toolbar.server_timing_stats.setdefault(self.panel_id, {}).update(data)
+
+    def get_server_timing_stats(self):
+        """
+        Access data stored by the panel. Returns a :class:`dict`.
+        """
+        return self.toolbar.server_timing_stats.get(self.panel_id, {})
+
     # Standard middleware methods
 
     def process_request(self, request):
@@ -192,6 +207,16 @@ def generate_stats(self, request, response):
         Does not return a value.
         """
 
+    def generate_server_timing(self, request, response):
+        """
+        Similar to :meth:`generate_stats
+        <debug_toolbar.panels.Panel.generate_stats>`,
+
+        Generate stats for Server Timing https://w3c.github.io/server-timing/
+
+        Does not return a value.
+        """
+
 
 # Backward-compatibility for 1.0, remove in 2.0.
 class DebugPanel(Panel):

debug_toolbar/panels/cache.py

@@ -244,3 +244,9 @@ def generate_stats(self, request, response):
             'misses': self.misses,
             'counts': self.counts,
         })
+
+    def generate_server_timing(self, request, response):
+        stats = self.get_stats()
+        value = stats.get('total_time', 0)
+        title = 'Cache {} Calls'.format(stats.get('total_calls', 0))
+        self.record_server_timing('total_time', title, value)

debug_toolbar/panels/sql/panel.py

@@ -240,3 +240,9 @@ def generate_stats(self, request, response):
             'queries': [q for a, q in self._queries],
             'sql_time': self._sql_time,
         })
+
+    def generate_server_timing(self, request, response):
+        stats = self.get_stats()
+        title = 'SQL {} queries'.format(len(stats.get('queries', [])))
+        value = stats.get('sql_time', 0)
+        self.record_server_timing('sql_time', title, value)

debug_toolbar/panels/timer.py

@@ -82,5 +82,13 @@ def generate_stats(self, request, response):
 
         self.record_stats(stats)
 
+    def generate_server_timing(self, request, response):
+        stats = self.get_stats()
+
+        self.record_server_timing('utime', 'User CPU time', stats.get('utime', 0))
+        self.record_server_timing('stime', 'System CPU time', stats.get('stime', 0))
+        self.record_server_timing('total', 'Total CPU time', stats.get('total', 0))
+        self.record_server_timing('total_time', 'Elapsed time', stats.get('total_time', 0))
+
     def _elapsed_ru(self, name):
         return getattr(self._end_rusage, name) - getattr(self._start_rusage, name)

debug_toolbar/toolbar.py

@@ -27,6 +27,7 @@ def __init__(self, request):
             panel_instance = panel_class(self)
             self._panels[panel_instance.panel_id] = panel_instance
         self.stats = {}
+        self.server_timing_stats = {}
         self.store_id = None
 
     # Manage panels

tests/panels/test_cache.py

@@ -47,3 +47,25 @@ def test_insert_content(self):
         self.panel.generate_stats(self.request, self.response)
         # ensure the panel renders correctly.
         self.assertIn('café', self.panel.content)
+
+    def test_generate_server_timin(self):
+        self.assertEqual(len(self.panel.calls), 0)
+        cache.cache.set('foo', 'bar')
+        cache.cache.get('foo')
+        cache.cache.delete('foo')
+
+        self.assertEqual(len(self.panel.calls), 3)
+
+        self.panel.generate_stats(self.request, self.response)
+        self.panel.generate_server_timing(self.request, self.response)
+
+        stats = self.panel.get_stats()
+
+        expected_data = {
+            'total_time': {
+                'title': 'Cache {} Calls'.format(stats['total_calls']),
+                'value': stats['total_time']
+            }
+        }
+
+        self.assertEqual(self.panel.get_server_timing_stats(), expected_data)

tests/panels/test_sql.py

@@ -48,6 +48,28 @@ def test_recording(self):
         # ensure the stacktrace is populated
         self.assertTrue(len(query[1]['stacktrace']) > 0)
 
+    def test_generate_server_timing(self):
+        self.assertEqual(len(self.panel._queries), 0)
+
+        list(User.objects.all())
+
+        self.panel.process_response(self.request, self.response)
+        self.panel.generate_stats(self.request, self.response)
+        self.panel.generate_server_timing(self.request, self.response)
+
+        # ensure query was logged
+        self.assertEqual(len(self.panel._queries), 1)
+        query = self.panel._queries[0]
+
+        expected_data = {
+            'sql_time': {
+                'title': 'SQL 1 queries',
+                'value': query[1]['duration']
+            }
+        }
+
+        self.assertEqual(self.panel.get_server_timing_stats(), expected_data)
+
     def test_non_ascii_query(self):
         self.assertEqual(len(self.panel._queries), 0)