From 68ca369f57bc47d2005cf5f9a99db3eebe843bc1 Mon Sep 17 00:00:00 2001 From: earthcomfy Date: Fri, 3 Jan 2025 21:36:27 +0300 Subject: [PATCH 1/5] Track and display middleware time in the toolbar --- debug_toolbar/middleware.py | 13 +++++++++++++ debug_toolbar/panels/timer.py | 9 +++++++++ debug_toolbar/toolbar.py | 1 + tests/test_integration.py | 1 + 4 files changed, 24 insertions(+) diff --git a/debug_toolbar/middleware.py b/debug_toolbar/middleware.py index 9986d9106..aca37723b 100644 --- a/debug_toolbar/middleware.py +++ b/debug_toolbar/middleware.py @@ -5,6 +5,7 @@ import re import socket from functools import cache +from time import perf_counter from asgiref.sync import iscoroutinefunction, markcoroutinefunction from django.conf import settings @@ -78,6 +79,8 @@ def __init__(self, get_response): markcoroutinefunction(self) def __call__(self, request): + # Start tracking middleware execution time + middleware_start_time = perf_counter() # Decide whether the toolbar is active for this request. if self.async_mode: return self.__acall__(request) @@ -98,10 +101,16 @@ def __call__(self, request): # regardless of the response. Keep 'return' clauses below. for panel in reversed(toolbar.enabled_panels): panel.disable_instrumentation() + middleware_end_time = perf_counter() + toolbar.middleware_time = ( + middleware_end_time - middleware_start_time + ) * 1000 return self._postprocess(request, response, toolbar) async def __acall__(self, request): + # Start tracking middleware execution time + middleware_start_time = perf_counter() # Decide whether the toolbar is active for this request. show_toolbar = get_show_toolbar() if not show_toolbar(request) or DebugToolbar.is_toolbar_request(request): @@ -125,6 +134,10 @@ async def __acall__(self, request): # regardless of the response. Keep 'return' clauses below. for panel in reversed(toolbar.enabled_panels): panel.disable_instrumentation() + middleware_end_time = perf_counter() + toolbar.middleware_time = ( + middleware_end_time - middleware_start_time + ) * 1000 return self._postprocess(request, response, toolbar) diff --git a/debug_toolbar/panels/timer.py b/debug_toolbar/panels/timer.py index 554798e7d..1a6f457b0 100644 --- a/debug_toolbar/panels/timer.py +++ b/debug_toolbar/panels/timer.py @@ -45,6 +45,10 @@ def content(self): (_("System CPU time"), _("%(stime)0.3f msec") % stats), (_("Total CPU time"), _("%(total)0.3f msec") % stats), (_("Elapsed time"), _("%(total_time)0.3f msec") % stats), + ( + _("Middleware time"), + _("%(middleware_time)0.3f msec") % stats, + ), ( _("Context switches"), _("%(vcsw)d voluntary, %(ivcsw)d involuntary") % stats, @@ -90,6 +94,8 @@ def generate_stats(self, request, response): # stats['urss'] = self._end_rusage.ru_idrss # stats['usrss'] = self._end_rusage.ru_isrss + # Add middleware time to stats + stats["middleware_time"] = self.toolbar.middleware_time self.record_stats(stats) def generate_server_timing(self, request, response): @@ -101,6 +107,9 @@ def generate_server_timing(self, request, response): self.record_server_timing( "total_time", "Elapsed time", stats.get("total_time", 0) ) + self.record_server_timing( + "middleware_time", "Middleware time", stats.get("middleware_time", 0) + ) def _elapsed_ru(self, name): return getattr(self._end_rusage, name) - getattr(self._start_rusage, name) diff --git a/debug_toolbar/toolbar.py b/debug_toolbar/toolbar.py index afb7affac..d1d2508d1 100644 --- a/debug_toolbar/toolbar.py +++ b/debug_toolbar/toolbar.py @@ -47,6 +47,7 @@ def __init__(self, request, get_response): self.stats = {} self.server_timing_stats = {} self.store_id = None + self.middleware_time = 0 self._created.send(request, toolbar=self) # Manage panels diff --git a/tests/test_integration.py b/tests/test_integration.py index 3cc0b1420..547dad1a5 100644 --- a/tests/test_integration.py +++ b/tests/test_integration.py @@ -605,6 +605,7 @@ def test_server_timing_headers(self): r'TimerPanel_stime;dur=(\d)*(\.(\d)*)?;desc="System CPU time", ', r'TimerPanel_total;dur=(\d)*(\.(\d)*)?;desc="Total CPU time", ', r'TimerPanel_total_time;dur=(\d)*(\.(\d)*)?;desc="Elapsed time", ', + r'TimerPanel_middleware_time;dur=(\d)*(\.(\d)*)?;desc="Middleware time", ', r'SQLPanel_sql_time;dur=(\d)*(\.(\d)*)?;desc="SQL 1 queries", ', r'CachePanel_total_time;dur=0;desc="Cache 0 Calls"', ] From 0c94a14d65a90d1957199af92123694295f59b4a Mon Sep 17 00:00:00 2001 From: earthcomfy Date: Fri, 3 Jan 2025 21:49:31 +0300 Subject: [PATCH 2/5] Update change log --- docs/changes.rst | 1 + 1 file changed, 1 insertion(+) diff --git a/docs/changes.rst b/docs/changes.rst index 4aa78cece..6df634441 100644 --- a/docs/changes.rst +++ b/docs/changes.rst @@ -9,6 +9,7 @@ Pending * Converted to Django Commons PyPI release process. * Fixed a crash which occurred when using non-``str`` static file values. * Documented experimental async support. +* Added middleware time to the timer panel. 5.0.0-alpha (2024-09-01) ------------------------ From 67147427b36aa8fe4849f5b2c003958695c2d2ef Mon Sep 17 00:00:00 2001 From: earthcomfy Date: Sat, 4 Jan 2025 08:38:31 +0300 Subject: [PATCH 3/5] Rename middleware_time to toolbar_time --- debug_toolbar/middleware.py | 16 ++++++---------- debug_toolbar/panels/timer.py | 10 +++++----- debug_toolbar/toolbar.py | 2 +- docs/changes.rst | 2 +- tests/test_integration.py | 2 +- 5 files changed, 14 insertions(+), 18 deletions(-) diff --git a/debug_toolbar/middleware.py b/debug_toolbar/middleware.py index aca37723b..4975c83a3 100644 --- a/debug_toolbar/middleware.py +++ b/debug_toolbar/middleware.py @@ -80,7 +80,7 @@ def __init__(self, get_response): def __call__(self, request): # Start tracking middleware execution time - middleware_start_time = perf_counter() + toolbar_start_time = perf_counter() # Decide whether the toolbar is active for this request. if self.async_mode: return self.__acall__(request) @@ -101,16 +101,14 @@ def __call__(self, request): # regardless of the response. Keep 'return' clauses below. for panel in reversed(toolbar.enabled_panels): panel.disable_instrumentation() - middleware_end_time = perf_counter() - toolbar.middleware_time = ( - middleware_end_time - middleware_start_time - ) * 1000 + toolbar_end_time = perf_counter() + toolbar.toolbar_time = (toolbar_end_time - toolbar_start_time) * 1000 return self._postprocess(request, response, toolbar) async def __acall__(self, request): # Start tracking middleware execution time - middleware_start_time = perf_counter() + toolbar_start_time = perf_counter() # Decide whether the toolbar is active for this request. show_toolbar = get_show_toolbar() if not show_toolbar(request) or DebugToolbar.is_toolbar_request(request): @@ -134,10 +132,8 @@ async def __acall__(self, request): # regardless of the response. Keep 'return' clauses below. for panel in reversed(toolbar.enabled_panels): panel.disable_instrumentation() - middleware_end_time = perf_counter() - toolbar.middleware_time = ( - middleware_end_time - middleware_start_time - ) * 1000 + toolbar_end_time = perf_counter() + toolbar.middleware_time = (toolbar_end_time - toolbar_start_time) * 1000 return self._postprocess(request, response, toolbar) diff --git a/debug_toolbar/panels/timer.py b/debug_toolbar/panels/timer.py index 1a6f457b0..d588e1390 100644 --- a/debug_toolbar/panels/timer.py +++ b/debug_toolbar/panels/timer.py @@ -46,8 +46,8 @@ def content(self): (_("Total CPU time"), _("%(total)0.3f msec") % stats), (_("Elapsed time"), _("%(total_time)0.3f msec") % stats), ( - _("Middleware time"), - _("%(middleware_time)0.3f msec") % stats, + _("Toolbar time"), + _("%(toolbar_time)0.3f msec") % stats, ), ( _("Context switches"), @@ -94,8 +94,8 @@ def generate_stats(self, request, response): # stats['urss'] = self._end_rusage.ru_idrss # stats['usrss'] = self._end_rusage.ru_isrss - # Add middleware time to stats - stats["middleware_time"] = self.toolbar.middleware_time + # Add toolbar time to stats + stats["toolbar_time"] = self.toolbar.toolbar_time self.record_stats(stats) def generate_server_timing(self, request, response): @@ -108,7 +108,7 @@ def generate_server_timing(self, request, response): "total_time", "Elapsed time", stats.get("total_time", 0) ) self.record_server_timing( - "middleware_time", "Middleware time", stats.get("middleware_time", 0) + "toolbar_time", "Toolbar time", stats.get("toolbar_time", 0) ) def _elapsed_ru(self, name): diff --git a/debug_toolbar/toolbar.py b/debug_toolbar/toolbar.py index d1d2508d1..d08659619 100644 --- a/debug_toolbar/toolbar.py +++ b/debug_toolbar/toolbar.py @@ -47,7 +47,7 @@ def __init__(self, request, get_response): self.stats = {} self.server_timing_stats = {} self.store_id = None - self.middleware_time = 0 + self.toolbar_time = 0 self._created.send(request, toolbar=self) # Manage panels diff --git a/docs/changes.rst b/docs/changes.rst index 6df634441..51421eeda 100644 --- a/docs/changes.rst +++ b/docs/changes.rst @@ -9,7 +9,7 @@ Pending * Converted to Django Commons PyPI release process. * Fixed a crash which occurred when using non-``str`` static file values. * Documented experimental async support. -* Added middleware time to the timer panel. +* Added toolbar time to the timer panel. 5.0.0-alpha (2024-09-01) ------------------------ diff --git a/tests/test_integration.py b/tests/test_integration.py index 547dad1a5..c748bce51 100644 --- a/tests/test_integration.py +++ b/tests/test_integration.py @@ -605,7 +605,7 @@ def test_server_timing_headers(self): r'TimerPanel_stime;dur=(\d)*(\.(\d)*)?;desc="System CPU time", ', r'TimerPanel_total;dur=(\d)*(\.(\d)*)?;desc="Total CPU time", ', r'TimerPanel_total_time;dur=(\d)*(\.(\d)*)?;desc="Elapsed time", ', - r'TimerPanel_middleware_time;dur=(\d)*(\.(\d)*)?;desc="Middleware time", ', + r'TimerPanel_toolbar_time;dur=(\d)*(\.(\d)*)?;desc="Toolbar time", ', r'SQLPanel_sql_time;dur=(\d)*(\.(\d)*)?;desc="SQL 1 queries", ', r'CachePanel_total_time;dur=0;desc="Cache 0 Calls"', ] From ebb75713de6f40cbe34468123636e7d423e14df1 Mon Sep 17 00:00:00 2001 From: earthcomfy Date: Wed, 8 Jan 2025 13:07:50 +0300 Subject: [PATCH 4/5] Measure full time of toolbar --- debug_toolbar/middleware.py | 9 --------- debug_toolbar/panels/timer.py | 11 +++++++++-- debug_toolbar/toolbar.py | 11 +++++++++-- 3 files changed, 18 insertions(+), 13 deletions(-) diff --git a/debug_toolbar/middleware.py b/debug_toolbar/middleware.py index 4975c83a3..9986d9106 100644 --- a/debug_toolbar/middleware.py +++ b/debug_toolbar/middleware.py @@ -5,7 +5,6 @@ import re import socket from functools import cache -from time import perf_counter from asgiref.sync import iscoroutinefunction, markcoroutinefunction from django.conf import settings @@ -79,8 +78,6 @@ def __init__(self, get_response): markcoroutinefunction(self) def __call__(self, request): - # Start tracking middleware execution time - toolbar_start_time = perf_counter() # Decide whether the toolbar is active for this request. if self.async_mode: return self.__acall__(request) @@ -101,14 +98,10 @@ def __call__(self, request): # regardless of the response. Keep 'return' clauses below. for panel in reversed(toolbar.enabled_panels): panel.disable_instrumentation() - toolbar_end_time = perf_counter() - toolbar.toolbar_time = (toolbar_end_time - toolbar_start_time) * 1000 return self._postprocess(request, response, toolbar) async def __acall__(self, request): - # Start tracking middleware execution time - toolbar_start_time = perf_counter() # Decide whether the toolbar is active for this request. show_toolbar = get_show_toolbar() if not show_toolbar(request) or DebugToolbar.is_toolbar_request(request): @@ -132,8 +125,6 @@ async def __acall__(self, request): # regardless of the response. Keep 'return' clauses below. for panel in reversed(toolbar.enabled_panels): panel.disable_instrumentation() - toolbar_end_time = perf_counter() - toolbar.middleware_time = (toolbar_end_time - toolbar_start_time) * 1000 return self._postprocess(request, response, toolbar) diff --git a/debug_toolbar/panels/timer.py b/debug_toolbar/panels/timer.py index d588e1390..6881557fe 100644 --- a/debug_toolbar/panels/timer.py +++ b/debug_toolbar/panels/timer.py @@ -94,8 +94,9 @@ def generate_stats(self, request, response): # stats['urss'] = self._end_rusage.ru_idrss # stats['usrss'] = self._end_rusage.ru_isrss - # Add toolbar time to stats - stats["toolbar_time"] = self.toolbar.toolbar_time + if hasattr(self, "_toolbar_start_time"): + stats["toolbar_time"] = (perf_counter() - self._toolbar_start_time) * 1000 + self.record_stats(stats) def generate_server_timing(self, request, response): @@ -113,3 +114,9 @@ def generate_server_timing(self, request, response): def _elapsed_ru(self, name): return getattr(self._end_rusage, name) - getattr(self._start_rusage, name) + + def enable_instrumentation(self): + self._toolbar_start_time = perf_counter() + + def aenable_instrumentation(self): + self._toolbar_start_time = perf_counter() diff --git a/debug_toolbar/toolbar.py b/debug_toolbar/toolbar.py index d08659619..0e6f67d50 100644 --- a/debug_toolbar/toolbar.py +++ b/debug_toolbar/toolbar.py @@ -47,7 +47,6 @@ def __init__(self, request, get_response): self.stats = {} self.server_timing_stats = {} self.store_id = None - self.toolbar_time = 0 self._created.send(request, toolbar=self) # Manage panels @@ -64,7 +63,15 @@ def enabled_panels(self): """ Get a list of panels enabled for the current request. """ - return [panel for panel in self._panels.values() if panel.enabled] + panels = [panel for panel in self._panels.values() if panel.enabled] + # Ensure TimerPanel is first in order to measure the full time of the toolbar's processing. + timer_panel = next( + (panel for panel in panels if panel.panel_id == "TimerPanel"), None + ) + if timer_panel: + panels.remove(timer_panel) + panels.insert(0, timer_panel) + return panels def get_panel_by_id(self, panel_id): """ From cb45e181cf900719793938a27829a57496c8d882 Mon Sep 17 00:00:00 2001 From: earthcomfy Date: Sat, 11 Jan 2025 21:36:29 +0300 Subject: [PATCH 5/5] Test timer panel is first in order --- tests/test_integration.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/tests/test_integration.py b/tests/test_integration.py index c748bce51..014353b3a 100644 --- a/tests/test_integration.py +++ b/tests/test_integration.py @@ -297,6 +297,10 @@ def test_concurrent_async_sql_page(self): len(response.toolbar.get_panel_by_id("SQLPanel").get_stats()["queries"]), 2 ) + def test_timer_panel_first(self): + toolbar = DebugToolbar(self.request, self.get_response) + self.assertEqual(toolbar.enabled_panels[0].panel_id, "TimerPanel") + @override_settings(DEBUG=True) class DebugToolbarIntegrationTestCase(IntegrationTestCase):