Track and display middleware time in the toolbar #2049
Conversation
|
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? |
|
@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. |
debug_toolbar/middleware.py
Outdated
| @@ -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() | |||
There was a problem hiding this comment.
We probably want to rename this to toolbar_ and update the text for it to be specific to the toolbar. Middleware may imply all of the middlewares together.
There was a problem hiding this comment.
Yes, that makes sense. I have renamed it.
debug_toolbar/middleware.py
Outdated
| @@ -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() | |||
There was a problem hiding this comment.
Sorry, I didn't go through this well enough earlier. What do you think about putting this start time in TimerPanel.enable_instrumentation? That way we put all of the timing logic in that specific panel and we avoid leaking it into the toolbar itself.
There was a problem hiding this comment.
Yes, added it to aenable_instrumentation as well
debug_toolbar/middleware.py
Outdated
| @@ -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() | |||
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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.
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:
docs/changes.rst.