Opened 8 years ago

Last modified 5 months ago

#25704 assigned New feature

Response time in WSGIRequestHandler.log_request

Reported by: Andrei Fokau Owned by: Tushar
Component: HTTP handling Version: dev
Severity: Normal Keywords:
Cc: Sarah Abderemane 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 (20)

comment:1 by Simon Charette, 8 years ago

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 8 years ago by Simon Charette (previous) (diff)

comment:2 by Andrei Fokau, 8 years ago

Description: modified (diff)
Triage Stage: AcceptedUnreviewed

comment:3 by Andrei Fokau, 8 years ago

Triage Stage: UnreviewedAccepted

comment:4 by Andrei Fokau, 8 years ago

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 8 years ago by Andrei Fokau (previous) (diff)

comment:5 by Simon Charette, 8 years ago

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

comment:6 by Andrei Fokau, 8 years ago

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 8 years ago by Andrei Fokau (previous) (diff)

comment:7 by Andrei Fokau, 8 years ago

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 by Keith Ganey, 8 years ago

Owner: changed from nobody to Keith Ganey
Status: newassigned

comment:9 by Andrei Fokau, 8 years ago

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

comment:10 by Andrei Fokau, 8 years ago

Easy pickings: unset

comment:11 by Andrei Fokau, 8 years ago

Owner: changed from Keith Ganey to Andrei Fokau

comment:12 by Tim Graham, 8 years ago

Patch needs improvement: set

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

comment:13 by Mariusz Felisiak, 2 years ago

Owner: Andrei Fokau removed
Status: assignednew

comment:14 by Tushar, 5 months ago

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

in reply to:  14 comment:15 by Natalia Bidart, 5 months ago

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!

comment:16 by Tushar, 5 months ago

Owner: set to Tushar
Status: newassigned

comment:17 by Sarah Abderemane, 5 months ago

Cc: Sarah Abderemane added

comment:18 by Tushar, 5 months ago

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?

comment:19 by Sarah Boyce, 5 months ago

Patch needs improvement: unset

comment:20 by Mariusz Felisiak, 5 months ago

Patch needs improvement: set
Note: See TracTickets for help on using tickets.
Back to Top