Opened 2 years ago

Last modified 23 months ago

#25704 assigned New feature

Response time in WSGIRequestHandler.log_request

Reported by: Andrei Fokau Owned by: Andrei Fokau
Component: HTTP handling Version: master
Severity: Normal Keywords:
Cc: Triage Stage: Accepted
Has patch: yes Needs documentation: no
Needs tests: no Patch needs improvement: yes
Easy pickings: no UI/UX: no

Description (last modified by Andrei Fokau)

It's often useful to know how much time it takes for runserver to respond without setting up a middleware or using the debug toolbar. Currently, one could monkeypatch WSGIRequestHandler (e.g. in manage.py) in order to get the time:

from django.core.servers.basehttp import WSGIRequestHandler
_handle = WSGIRequestHandler.handle

def handle(self):
    self.request_started = time.time()
    _handle(self)

def log_request(self, code='-', size='-'):
    self.log_message('"%s" %s %s %dms',
                     self.requestline, str(code), str(size),
                     (time.time() - self.request_started) * 1e3)

WSGIRequestHandler.handle = handle
WSGIRequestHandler.log_request = log_request

or via middleware

class ResponseTimeMiddleware(object):
    def process_view(self, request, view_func, view_args, view_kwargs):
        start = time.time()
        response = view_func(request, *view_args, **view_kwargs)

        if response and getattr(response, 'is_rendered', True) is False:
            response.rendered_content

        logging.getLogger('response_time').debug(
            'Response time %dms', (time.time() - start) * 1000)
        return response

It seems easy to add it in the WSGIRequestHandler e.g. https://github.com/django/django/pull/5606. The response time is slightly longer than actual response time due to late measuring but think an easy implementation is better than the exact duration.

This feature is blocked by https://code.djangoproject.com/ticket/25684

Change History (12)

comment:1 Changed 2 years ago by Simon Charette

Description: modified (diff)
Triage Stage: UnreviewedAccepted

I'm not sure this should be part of the actual output of runserver but it would make sense to at least provide it as a kwarg to the logger calls to allow third party and users to refer to it in a formater or filter.

e.g. one could write a formatter that turns the text bold if request take more than X ms to complete.

Last edited 2 years ago by Simon Charette (previous) (diff)

comment:2 Changed 2 years ago by Andrei Fokau

Description: modified (diff)
Triage Stage: AcceptedUnreviewed

comment:3 Changed 2 years ago by Andrei Fokau

Triage Stage: UnreviewedAccepted

comment:4 Changed 2 years ago by Andrei Fokau

Kwarg sounds fine to me, but in this case we need kwargs for the other parts which requires overriding log_request instead of log_format. If this is ok then I will make a PR to #25684 (https://github.com/fcurella/django/tree/runserver-logging) to help with the change. As soon as it's done, adding response time should be trivial.

Last edited 2 years ago by Andrei Fokau (previous) (diff)

comment:5 Changed 2 years ago by Simon Charette

By kwargs I meant using the extra kwarg of logger.log().

comment:6 Changed 2 years ago by Andrei Fokau

Example of time:

[07/Nov/2015 17:37:05] "GET /inbox/ HTTP/1.1" 200 216874 5301ms
[07/Nov/2015 17:37:05] "GET /static/CACHE/css/f090a416387d.css HTTP/1.1" 304 0 4ms
[07/Nov/2015 17:37:05] "GET /static/CACHE/css/df20af4b0d04.css HTTP/1.1" 304 0 3ms
[07/Nov/2015 17:37:05] "GET /static/img/logo.svg HTTP/1.1" 304 0 2ms
Last edited 2 years ago by Andrei Fokau (previous) (diff)

comment:7 Changed 2 years ago by Andrei Fokau

If #25684 will change order of parts in the log message, we could have something like

[07/Nov/2015 17:37:05] HTTP/1.1 200 "GET /inbox/" 216874 5301ms
[07/Nov/2015 17:37:05] HTTP/1.1 304 "GET /static/CACHE/css/f090a416387d.css" 0 4ms
[07/Nov/2015 17:37:05] HTTP/1.1 304 "GET /static/CACHE/css/df20af4b0d04.css" 0 3ms
[07/Nov/2015 17:37:05] HTTP/1.1 304 "GET /static/img/logo.svg" 0 2ms

comment:8 Changed 2 years ago by Keith Ganey

Owner: changed from nobody to Keith Ganey
Status: newassigned

comment:9 Changed 2 years ago by Andrei Fokau

Hi @kganey, I would rather fix it myself as soon as #25684 is closed. Sorry for Easy picking

comment:10 Changed 2 years ago by Andrei Fokau

Easy pickings: unset

comment:11 Changed 2 years ago by Andrei Fokau

Owner: changed from Keith Ganey to Andrei Fokau

comment:12 Changed 23 months ago by Tim Graham

Patch needs improvement: set

Marking as "patch needs improvement" until it's updated after #25684 is merged.

Note: See TracTickets for help on using tickets.
Back to Top