Response time in WSGIRequestHandler.log_request

[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

[Simon Charette]

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 latest more than X ms.

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

[Simon Charette]

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

[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

[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

[Andrei Fokau]

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

[Tim Graham]

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

[Tushar]

Is this issue still relevant? I would like to make a PR for this.

[Natalia Bidart]

Replying to Tushar:

Is this issue still relevant? I would like to make a PR for this.

After reading the comments it seems so! Please go ahead and assign it to you if you are ready to work on this. Thanks!

[Tushar]

Needed clarification on whether this should be an optional feature or should it be there by default. Also, am I correct in my assumption that the response time should be the amount of time the WSGI application takes to process the request and send a response?