Track and display middleware time in the toolbar by earthcomfy · Pull Request #2049 · django-commons/django-debug-toolbar

earthcomfy · 2025-01-03T18:50:16Z

Description

CPU time includes the debug toolbar's own time so this PR aims to track how long the middleware takes to run and display that time on the panel.

Fixes #1903

Checklist:

I have added the relevant tests for this change.
I have added an item to the Pending section of docs/changes.rst.

robhudson · 2025-01-03T19:31:59Z

Would it make sense to include a stat with the middleware time deducted from the total for the user? Or deduct it from the existing total?

tim-schilling · 2025-01-03T22:12:53Z

@robhudson the thinking I had earlier was that the toolbar changes the application so we shouldn't try to extract the toolbar itself from the timing.

tim-schilling · 2025-01-07T01:03:20Z

            # regardless of the response. Keep 'return' clauses below.
            for panel in reversed(toolbar.enabled_panels):
                panel.disable_instrumentation()
+            toolbar_end_time = perf_counter()


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?

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.

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

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

@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.

tim-schilling · 2025-01-14T02:21:35Z

+        if timer_panel:
+            panels.remove(timer_panel)
+            panels.insert(0, timer_panel)
+        return panels


@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?

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.

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.

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.

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

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)

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

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

tim-schilling · 2025-09-20T13:20:31Z

@earthcomfy do you have time to pick this back up? If not, @robhudson could ask a Djangonaut from the next session of Djangonaut Space to get it over the finish line.

earthcomfy · 2025-09-20T15:41:10Z

@tim-schilling Thanks for following up! I don’t think I’ll have time to return to this, so feel free to reassign it:)

…hod to async

earthcomfy · 2026-03-18T10:54:45Z

Hey @tim-schilling, I'd like to pick this back up if that's okay.

I checked this again, and I believe what @elineda pointed out is correct. I have verified manually as well that the change doesn't affect the order of the panels. The template (base.html) iterates over toolbar.panels, which returns self._panels.values() directly (the original order from settings). The enabled_panels property creates a separate list for processing order only. doesn't mutate _panels.

That said, if the team still prefers the other approach of storing timing on the DebugToolbar instance directly, I'm happy to go that route instead.

PS: fixed the conflict and updated my branch to the latest.

tim-schilling · 2026-03-18T13:20:28Z

Awesome, glad to hear you can work on it again! I've got this on my list of things to review. I don't have a timetable though.

github-actions · 2026-03-18T13:29:32Z

Coverage report

Click to see where and how coverage changed

File	Statements	Missing	Coverage	Coverage (new stmts)	Lines missing
debug_toolbar
toolbar.py
debug_toolbar/panels
timer.py
Project Total

_{This report was generated by python-coverage-comment-action}

codingjoe

Hi @earthcomfy, I invested some time to give this a thorough code review. Please tell me if you want me to clarify some of my comments. Cheers! Joe

codingjoe · 2026-04-18T14:51:57Z

            #        stats['usrss'] = self._end_rusage.ru_isrss

+        if hasattr(self, "_toolbar_start_time"):
+            stats["toolbar_time"] = (perf_counter() - self._toolbar_start_time) * 1000


Consider storing the duration with an explicit type using datetime.timedelta. It's always easier than remembering that toolbar_time is in milliseconds.

codingjoe · 2026-04-18T14:55:04Z

            #        stats['urss'] = self._end_rusage.ru_idrss
            #        stats['usrss'] = self._end_rusage.ru_isrss

+        if hasattr(self, "_toolbar_start_time"):


EAFP: Maybe consider catching the AttributeError instead of the default if-branch.

codingjoe · 2026-04-18T14:57:41Z

+    def enable_instrumentation(self):
+        self._toolbar_start_time = perf_counter()
+
+    async def aenable_instrumentation(self):
+        self._toolbar_start_time = perf_counter()


Both are synchronous, and instrumentation usually lives in the CPU and has no IO. Thus, I don't think asyncIO is all that helpful even in the future.

codingjoe · 2026-04-18T14:59:00Z

+        timer_panel = next(
+            (panel for panel in panels if panel.panel_id == "TimerPanel"), None
+        )
+        if timer_panel:


Great place for a walrus:

Suggested change

timer_panel = next(

(panel for panel in panels if panel.panel_id == "TimerPanel"), None

)

if timer_panel:

if timer_panel := next(

(panel for panel in panels if panel.panel_id == "TimerPanel"), None

)

codingjoe · 2026-04-18T15:02:27Z

+            panels.remove(timer_panel)
+            panels.insert(0, timer_panel)


Maybe replace the item instead of the stack operation.

Suggested change

panels.remove(timer_panel)

panels.insert(0, timer_panel)

panels[0] = timer_panel

codingjoe · 2026-04-18T15:04:15Z

+        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
+        )


You are looping over the panels twice, O(n)=2*n. I think with a little rearrangement, this can be done in a single loop.

codingjoe · 2026-04-18T15:06:22Z

            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", ',


Toolbar is ambiguous outside this repo. Maybe stick with DebugToolbar, like it's currently phrased in most places.

Suggested change

r'TimerPanel_toolbar_time;dur=(\d)*(\.(\d)*)?;desc="Toolbar time", ',

r'TimerPanel_dj_toolbar_time;dur=(\d)*(\.(\d)*)?;desc="DebugToolbar time", ',

codingjoe · 2026-04-18T15:07:45Z

            (_("Total CPU time"), _("%(total)0.3f ms") % stats),
            (_("Elapsed time"), _("%(total_time)0.3f ms") % stats),
+            (
+                _("Toolbar time"),


Toolbar is ambiguous outside this repo. Maybe stick with DebugToolbar, like it's currently phrased in most places.

Suggested change

_("Toolbar time"),

_("DebugToolbar time"),

earthcomfy added 2 commits January 3, 2025 21:36

Track and display middleware time in the toolbar

68ca369

Update change log

0c94a14

tim-schilling reviewed Jan 3, 2025

View reviewed changes

Comment thread debug_toolbar/middleware.py Outdated

Rename middleware_time to toolbar_time

6714742

earthcomfy requested a review from tim-schilling January 4, 2025 06:34

tim-schilling reviewed Jan 7, 2025

View reviewed changes

Comment thread debug_toolbar/middleware.py Outdated

tim-schilling reviewed Jan 7, 2025

View reviewed changes

Measure full time of toolbar

ebb7571

earthcomfy requested a review from tim-schilling January 8, 2025 10:14

earthcomfy added 2 commits January 11, 2025 19:23

Merge branch 'main' into include_middleware_time

e029174

Test timer panel is first in order

cb45e18

tim-schilling reviewed Jan 14, 2025

View reviewed changes

earthcomfy added 2 commits March 18, 2026 11:22

Merge branch 'main' into include_middleware_time

6715a21

Fix formatting of toolbar time display and change instrumentation met…

df7fc44

…hod to async

codingjoe reviewed Apr 18, 2026

View reviewed changes

	panels.remove(timer_panel)
	panels.insert(0, timer_panel)
	panels[0] = timer_panel

	r'TimerPanel_toolbar_time;dur=(\d)(\.(\d))?;desc="Toolbar time", ',
	r'TimerPanel_dj_toolbar_time;dur=(\d)(\.(\d))?;desc="DebugToolbar time", ',

Conversation

earthcomfy commented Jan 3, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

Checklist:

Uh oh!

robhudson commented Jan 3, 2025

Uh oh!

tim-schilling commented Jan 3, 2025

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tim-schilling Jan 14, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

elineda Feb 13, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tim-schilling commented Sep 20, 2025

Uh oh!

earthcomfy commented Sep 20, 2025

Uh oh!

earthcomfy commented Mar 18, 2026

Uh oh!

tim-schilling commented Mar 18, 2026

Uh oh!

github-actions Bot commented Mar 18, 2026

Coverage report

Uh oh!

codingjoe left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

earthcomfy commented Jan 3, 2025 •

edited

Loading

tim-schilling Jan 14, 2025 •

edited

Loading

elineda Feb 13, 2025 •

edited

Loading