[Django] #25704: Response time in WSGIRequestHandler.log_request
Django
-------------------------------+--------------------
Reporter: andreif | Owner: nobody
Type: New feature | Status: new
Component: HTTP handling | Version: master
Severity: Normal | Keywords:
Triage Stage: Unreviewed | Has patch: 1
Easy pickings: 1 | UI/UX: 0
-------------------------------+--------------------
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:
{{{
#!python
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
}}}
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
--
Ticket URL: <https://code.djangoproject.com/ticket/25704>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
Django
Reporter: andreif | Owner: nobody
Type: New feature | Status: new
Component: HTTP handling | Version: master
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 1 | UI/UX: 0
Changes (by charettes):
* needs_better_patch: => 0
* stage: Unreviewed => Accepted
* needs_tests: => 0
* needs_docs: => 0
Old description:
> 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:
>
> {{{
> #!python
> 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
> }}}
>
> 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
New description:
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:
{{{
#!python
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
}}}
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
--
Comment:
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.
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:1>
Django
Reporter: andreif | Owner: nobody
Type: New feature | Status: new
Component: HTTP handling | Version: master
Keywords: | Triage Stage: Unreviewed
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Changes (by andreif):
* stage: Accepted => Unreviewed
Old description:
> 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:
>
> {{{
> #!python
> 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
> }}}
>
> 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
New description:
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:
{{{
#!python
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
{{{
#!python
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
--
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:2>
Django
Reporter: andreif | Owner: nobody
Type: New feature | Status: new
Component: HTTP handling | Version: master
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Changes (by andreif):
* stage: Unreviewed => Accepted
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:3>
Django
Reporter: andreif | Owner: nobody
Type: New feature | Status: new
Component: HTTP handling | Version: master
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Comment (by andreif):
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`. I
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.
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:4>
Django
Reporter: andreif | Owner: nobody
Type: New feature | Status: new
Component: HTTP handling | Version: master
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Comment (by charettes):
By kwargs I meant using the `extra` kwarg of `logger.log()`.
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:5>
Django
Reporter: andreif | Owner: nobody
Type: New feature | Status: new
Component: HTTP handling | Version: master
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Comment (by andreif):
Example of time:
{{{
[07/Nov/2015 17:37:05] "GET /inbox/ HTTP/1.1" 200 216874 0ms 5301ms
[07/Nov/2015 17:37:05] "GET /static/CACHE/css/f090a416387d.css HTTP/1.1"
304 0 0ms 4ms
[07/Nov/2015 17:37:05] "GET /static/CACHE/css/df20af4b0d04.css HTTP/1.1"
304 0 0ms 3ms
[07/Nov/2015 17:37:05] "GET /static/img/logo.svg HTTP/1.1" 304 0 0ms 2ms
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:6>
Django
Reporter: andreif | Owner: nobody
Type: New feature | Status: new
Component: HTTP handling | Version: master
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Comment (by andreif):
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
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:7>
Django
Reporter: andreif | Owner: kganey
Type: New feature | Status: assigned
Component: HTTP handling | Version: master
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Changes (by kganey):
* status: new => assigned
* owner: nobody => kganey
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:8>
Django
Reporter: andreif | Owner: kganey
Type: New feature | Status: assigned
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Comment (by andreif):
Hi @kganey, I would rather fix it myself as soon as #25684 is closed.
Sorry for Easy picking
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:9>
Django
Reporter: andreif | Owner: kganey
Type: New feature | Status: assigned
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
-------------------------------+------------------------------------
Changes (by andreif):
* easy: 1 => 0
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:10>
Django
Reporter: andreif | Owner: andreif
Type: New feature | Status: assigned
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------+------------------------------------
Changes (by andreif):
* owner: kganey => andreif
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:11>
Django
Reporter: andreif | Owner: andreif
Type: New feature | Status: assigned
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------+------------------------------------
* needs_better_patch: 0 => 1
Comment:
Marking as "patch needs improvement" until it's updated after #25684 is
merged.
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:12>
Django
Reporter: Andrei Fokau | Owner: (none)
Type: New feature | Status: new
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------+------------------------------------
* owner: Andrei Fokau => (none)
* status: assigned => new
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:13>
Django
Reporter: Andrei Fokau | Owner: (none)
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------+------------------------------------
Comment (by Tushar):
Is this issue still relevant? I would like to make a PR for this.
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:14>
Django
Reporter: Andrei Fokau | Owner: (none)
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------+------------------------------------
Comment (by Natalia Bidart):
Replying to [comment:14 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!
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:15>
Django
Reporter: Andrei Fokau | Owner: Tushar
Type: New feature | Status: assigned
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------+------------------------------------
* owner: (none) => Tushar
* status: new => assigned
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:16>
Django
Reporter: Andrei Fokau | Owner: Tushar
Type: New feature | Status: assigned
Component: HTTP handling | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------+------------------------------------
* cc: Sarah Abderemane (added)
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:17>
Django
Reporter: Andrei Fokau | Owner: Tushar
Type: New feature | Status: assigned
Component: HTTP handling | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------+------------------------------------
Comment (by 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?
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:18>
Django
Reporter: Andrei Fokau | Owner: Tushar
Type: New feature | Status: assigned
Component: HTTP handling | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------+------------------------------------
* needs_better_patch: 1 => 0
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:19>
Django
Reporter: Andrei Fokau | Owner: Tushar
Type: New feature | Status: assigned
Component: HTTP handling | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------+------------------------------------
* needs_better_patch: 0 => 1
--
Ticket URL: <https://code.djangoproject.com/ticket/25704#comment:20>