CPU Time includes DJDT's own time

[vanschelven]

The CPU Time displayed in the DJDT shows the total time taken to render the request, including the time to render the DJDT itself. This is not what I care about, because the DJDT will not be there when running in production.

Is it possible to get the time elapsed of the actual rendered view on-screen somewhere?

[tim-schilling]

If you're looking for metrics on the app running in production, I'd suggest looking into an APM product or an observability product.

[vanschelven]

I don't think I said that although I see how what I said could be interpreted in that way. Let me clarify: in my case, the number as-shown was for c. 90% caused by the DJDT itself. Because I was in the assumption that the DJDT was saying something (mostly) about my code, rather than about itself, this led me on a wild goose chase, searching for the slowness in my application. This could have been prevented if the DJDT time/cpu panel had one or 2 lines about the "thing under measurement" explicitly

[tim-schilling]

I appreciate the clarification.

I can see how that is a problem. I suspect it's possible for the tollbar middleware to track how long it's been running, then present that in the response along side the overall time.

I'm not sure we'd want to do the subtraction automatically because the total time is the total time. The toolbar is a part of the application.

Is that something you're interested in creating a PR for?

[vanschelven]

Is that something you're interested in creating a PR for?

"maybe"... I'll let you know :smile:

[earthcomfy]

@tim-schilling Hey, I was hoping to make a PR for this and wanted to clarify. Are we going to measure the middleware time from the start to the end of the middleware's execution (?) something like this:

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)
    # 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):
        return self.get_response(request)
    toolbar = DebugToolbar(request, self.get_response)
    # Activate instrumentation ie. monkey-patch.
    for panel in toolbar.enabled_panels:
        panel.enable_instrumentation()
    try:
        # Run panels like Django middleware.
        response = toolbar.process_request(request)
    finally:
        clear_stack_trace_caches()
        # Deactivate instrumentation ie. monkey-unpatch. This must run
        # 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  # in milliseconds

    return self._postprocess(request, response, toolbar)

Thank you:)

[tim-schilling]

Yeah, I think that's the general idea :rocket:

Some initial thoughts:

• What about pulling this timing logic out into a separate class to manage? That may be over-engineering though
• It'll need to handle the __acall__ path too

[earthcomfy]

Thanks; I made a PR without pulling it out to a separate class. But if that's required, we could do something like this

from time import perf_counter


class TimingManager:
    def __init__(self):
        self.start_time = None
        self.end_time = None

    def start(self):
        self.start_time = perf_counter()

    def stop(self):
        self.end_time = perf_counter()

    def elapsed_time(self):
        if self.start_time is None or self.end_time is None:
            return 0
        return (self.end_time - self.start_time) * 1000

and then call this manager in the middleware. I have created a PR but let me know if this needs to be added.