Opened 9 years ago
Last modified 12 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 )
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 , 9 years ago
Description: | modified (diff) |
---|---|
Triage Stage: | Unreviewed → Accepted |
comment:2 by , 9 years ago
Description: | modified (diff) |
---|---|
Triage Stage: | Accepted → Unreviewed |
comment:3 by , 9 years ago
Triage Stage: | Unreviewed → Accepted |
---|
comment:4 by , 9 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.
comment:6 by , 9 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
comment:7 by , 9 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 , 9 years ago
Owner: | changed from | to
---|---|
Status: | new → assigned |
comment:9 by , 9 years ago
Hi @kganey, I would rather fix it myself as soon as #25684 is closed. Sorry for Easy picking
comment:10 by , 9 years ago
Easy pickings: | unset |
---|
comment:11 by , 9 years ago
Owner: | changed from | to
---|
comment:12 by , 9 years ago
Patch needs improvement: | set |
---|
Marking as "patch needs improvement" until it's updated after #25684 is merged.
comment:13 by , 3 years ago
Owner: | removed |
---|---|
Status: | assigned → new |
follow-up: 15 comment:14 by , 13 months ago
Is this issue still relevant? I would like to make a PR for this.
comment:15 by , 13 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 , 13 months ago
Owner: | set to |
---|---|
Status: | new → assigned |
comment:17 by , 13 months ago
Cc: | added |
---|
comment:18 by , 13 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 , 13 months ago
Patch needs improvement: | unset |
---|
comment:20 by , 12 months ago
Patch needs improvement: | set |
---|
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.