Skip to content

Track and display middleware time in the toolbar #2049

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 6 commits into
base: main
Choose a base branch
from
Open

Track and display middleware time in the toolbar #2049

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
68ca369
Track and display middleware time in the toolbar
earthcomfy Jan 3, 2025
0c94a14
Update change log
earthcomfy Jan 3, 2025
6714742
Rename middleware_time to toolbar_time
earthcomfy Jan 4, 2025
ebb7571
Measure full time of toolbar
earthcomfy Jan 8, 2025
e029174
Merge branch 'main' into include_middleware_time
earthcomfy Jan 11, 2025
cb45e18
Test timer panel is first in order
earthcomfy Jan 11, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 16 additions & 0 deletions debug_toolbar/panels/timer.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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),
(
_("Toolbar time"),
_("%(toolbar_time)0.3f msec") % stats,
),
(
_("Context switches"),
_("%(vcsw)d voluntary, %(ivcsw)d involuntary") % stats,
Expand Down Expand Up @@ -90,6 +94,9 @@ def generate_stats(self, request, response):
# stats['urss'] = self._end_rusage.ru_idrss
# stats['usrss'] = self._end_rusage.ru_isrss

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):
Expand All @@ -101,6 +108,15 @@ def generate_server_timing(self, request, response):
self.record_server_timing(
"total_time", "Elapsed time", stats.get("total_time", 0)
)
self.record_server_timing(
"toolbar_time", "Toolbar time", stats.get("toolbar_time", 0)
)

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()
10 changes: 9 additions & 1 deletion debug_toolbar/toolbar.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -63,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
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@earthcomfy I'm going to need to take a bit to process this. This is a bit of a change and I want to make sure I understand it well. For example, I think this impacts the order of the panels on the side which means it impacts the UX of the toolbar.

Currently by default the Timer panel is 3rd from the top, while the top is the History panel. I think the History panel being at the top is between mildly important and important.

@django-commons/django-debug-toolbar any thoughts here?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I agree that the history panel should stay at the top because it affects basically everything show below.

Maybe we could unconditionally (without checking if the timer panel is even used) save the start time of the toolbar in the middleware or in the DebugToolbar instance. The timer panel could then use self.toolbar or something to access this timing information if it's enabled.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've been going back and forth on that. I was hoping we could contain this entirely within the TimerPanel, but that may be more problematic than we'd like.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, it would be great if there was a way to keep it contained. But if the price we pay for that is that we either have to introduce a pre-init API or some way of ordering panels processing (priority? weight?) then I'd slightly prefer to keep the amount of code required down while uglifying things a bit. This isn't a strongly held conviction though.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, that adds a fair amount of complexity. I'm leaning towards agreeing with you. @earthcomfy what do you think?

Copy link
Member

@elineda elineda Feb 13, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The order on the ux is not affected by these changes isn't ?
The display order is calculated by the DebugToolbar.panels (debug_toolbar/toolbar.py:33), not DebugToolbar.enabled_panels (debug_toolbar/toolbar.py:62)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe it is. They both end up coming from settings.get_panels()

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But the change isn't in the settings, it's ont the panel enabled.


def get_panel_by_id(self, panel_id):
"""
Expand Down
1 change: 1 addition & 0 deletions docs/changes.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@ Pending
* Fixed a crash which occurred when using non-``str`` static file values.
* Documented experimental async support.
* Improved troubleshooting doc for incorrect mime types for .js static files
* Added toolbar time to the timer panel.

5.0.0-alpha (2024-09-01)
------------------------
Expand Down
5 changes: 5 additions & 0 deletions tests/test_integration.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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):
Expand Down Expand Up @@ -605,6 +609,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_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"',
]
Expand Down