Add elapsed request time to the development server log

[Vaughn Koch]

When doing performance testing on your code, it's helpful to see how long a request takes to be served.
This ticket/patch adds the elapsed time in seconds to the end of each HTTP request line in the development server log.

Example:

Validating models...
0 errors found

Django version 1.2.1, using settings 'weeplaces.settings'
Development server is running at http://127.0.0.1:8000/
Quit the server with CTRL-BREAK.
[07/Nov/2010 15:57:17] "GET / HTTP/1.1" 200 11308 0.26
[07/Nov/2010 15:57:27] "GET /media/css/reset.css HTTP/1.1" 304 0 0.05

The 0.26 for the first GET request indicates that it took a quarter of a second to serve the root page.

[Vaughn Koch]

Change to basehttp.py to time an HTTP query and display it in the dev server log.

[Vaughn Koch]

Accepted ticket as per instructions in 'Submitting patches' on this site.

[Paul McMillan]

This strikes me as useful functionality. It fits well alongside the size of the request, and would be very helpful for first-order debugging.

The problem with the patch as it currently stands is that it breaks our (pseudo) compatibility with the ​common log format. Since we omit the first few standard fields anyway, compatibility doesn't seem to be the goal, but I'd like a core dev to weigh in on how this should be formatted. I don't think this is important enough to have a separate runtime option.

Personally, I'm +1 leaving it where it is in the included patch, or +0 for moving it to the front of the line.

[Gabriel Hurley]

Personally, I'm -0 on it...

1. There are numerous other (better) tools for telling you how long a whole request took: firebug and the chrome developer console spring to mind immediately. I'd much rather look at their graphical output of that data.

2. The overall time taken by an individual request isn't going to tell you anything useful except in the case of a *very* long (possibly broken) request-response cycle.

3. Following on 2, there are much better tools for profiling python code, in much more granular ways... at the very least, for profiling purposes, you need to know how much time was spent in which pieces of code, not the overall request time.

4. The time it takes to serve an individual request varies somewhat, and may be affected by other disk/CPU activity. Proper profiling requires averages across numerous repetitions of the same code.

5. Adding this function is just an extra bit of overhead (albeit minor) for each request served by the dev server.

While I'm +1 on making profiling easier, I don't see this as being a significant improvement. At the same time, I don't see any substantial downsides (other than those noted by PaulM) to adding it. Hence my -0.

[Paul McMillan]

On further reflection, I'm -0 on this. The variance due to factors beyond Django's control (disk, memory, etc.) means that these values will fluctuate wildly. These numbers are likely to be misleading, particularly to a new developer, since any given data sample isn't very meaningful all by itself.

[anonymous]

Hehe no worries guys. Just a couple of thoughts:

• I use firebug daily, and sometimes it's hard to cut through all the mess when looking at the timings. I've personally used this log-timing patch to make improvements in my views.
  
• There is a difference between the total time it takes to serve a Django view and the total roundtrip time from the browser's viewpoint. You can't do the first one just using Firebug.
  
• You can easily address (2) and (4) by calling the view multiple times and looking at a few instances of the data - you'd have to do this with a profiler in any case.
  
• Also, I use profiling tools as well - they're more precise, but also much more heavyweight. Sometimes you just need the insight of 'hey, that view is taking 1 second instead of 0.05 seconds...'
  

[Vaughn Koch]

Replying to anonymous: Sorry, wasn't logged in when I posted this.

Hehe no worries guys. Just a couple of thoughts:

• I use firebug daily, and sometimes it's hard to cut through all the mess when looking at the timings. I've personally used this log-timing patch to make improvements in my views.
  
• There is a difference between the total time it takes to serve a Django view and the total roundtrip time from the browser's viewpoint. You can't do the first one just using Firebug.
  
• You can easily address (2) and (4) by calling the view multiple times and looking at a few instances of the data - you'd have to do this with a profiler in any case.
  
• Also, I use profiling tools as well - they're more precise, but also much more heavyweight. Sometimes you just need the insight of 'hey, that view is taking 1 second instead of 0.05 seconds...'
  

[Julien Phalip]

I'm -0 for the same reasons as the ones mentioned by PaulM and gabrielhurley. I'm not sure how many -0's are required for a wontfix, but I'll go ahead and wontfix this for it adds marginal benefit and the information displayed would be inaccurate anyway. Thank you for the suggestion though.

[Jacob]

Milestone 1.3 deleted