Skip to content
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

Track and display middleware time in the toolbar #2049

Open
wants to merge 6 commits into
base: main
Choose a base branch
from
+31 −1
Open

Track and display middleware time in the toolbar #2049

Show file tree
Hide file tree
Changes from 3 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
9 changes: 9 additions & 0 deletions debug_toolbar/middleware.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -78,6 +79,8 @@ def __init__(self, get_response):
markcoroutinefunction(self)

def __call__(self, request):
# Start tracking middleware execution time
toolbar_start_time = perf_counter()
tim-schilling marked this conversation as resolved.
Show resolved Hide resolved
# Decide whether the toolbar is active for this request.
if self.async_mode:
return self.__acall__(request)
Expand All @@ -98,10 +101,14 @@ 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()
Copy link
Member

Choose a reason for hiding this comment

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

The other thing I was thinking about is how to handle measuring the full time of the toolbar's processing. This is actually stopping before all the Panel.generate_stats() methods are called which contains quite a bit of logic. I think ideally we'd capture that in this timing.

The problem is, how do we capture that? I have a few ideas, but I'm not happy with them.

I think we could measure the end time in TimerPanel.generate_stats() like we do with the rest and store it. This means any other panels that generate their stats after the TimerPanel would not be included. To mitigate that, we could find a way to make sure that TimerPanel is first to enable and last to generate stats. I think having it be first in enabled_panels would do the trick.

The other idea I had was to create a templatetag that would do the diff between the stored time and the current time at the time the toolbar is rendered. The problem here is that it wouldn't be compatible with the serializable branch where we want to store all the stats before rendering.

So I think trying to consolidate all the logic into TimerPanel with a change to force TimerPanel to be first for processing (not appearance on the idea) is ideal.

@salty-ivy @elineda any thoughts?

Copy link
Author

Choose a reason for hiding this comment

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

I have updated the enabled_panels property to ensure the TimerPanel is first in order. This is I think what you meant by in the first approach. The order of enabled panels is reversed in _postprocess ensuring the end time is captured at the end.

Copy link
Member

Choose a reason for hiding this comment

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

Excellent, thank you @earthcomfy! This is looking really nice. The last bit we need are the tests.

Copy link
Author

Choose a reason for hiding this comment

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

I added a test to ensure the timer panel is first. Are there any other tests that need to be included

Copy link
Member

@tim-schilling tim-schilling Jan 14, 2025 •
edited
Loading

Choose a reason for hiding this comment

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

@earthcomfy ideally we'd have tests covering all the changes on the Timer panel. Or updates to similar tests to also cover these new fields.

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):
Expand All @@ -125,6 +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()
toolbar_end_time = perf_counter()
toolbar.middleware_time = (toolbar_end_time - toolbar_start_time) * 1000

return self._postprocess(request, response, toolbar)

Expand Down
9 changes: 9 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,8 @@ 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
self.record_stats(stats)

def generate_server_timing(self, request, response):
Expand All @@ -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(
"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)
1 change: 1 addition & 0 deletions debug_toolbar/toolbar.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -47,6 +47,7 @@ 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
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 @@ -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 toolbar time to the timer panel.

5.0.0-alpha (2024-09-01)
------------------------
Expand Down
1 change: 1 addition & 0 deletions tests/test_integration.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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_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