Opened 4 years ago

Closed 4 years ago

Last modified 4 years ago

#14640 closed Uncategorized (wontfix)

Add elapsed request time to the development server log

Reported by: vaughnkoch Owned by: vaughnkoch
Component: HTTP handling Version: 1.2
Severity: Normal Keywords: log time development server
Cc: Triage Stage: Accepted
Has patch: yes Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: UI/UX:

Description

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.

Attachments (1)

timing.patch (1.2 KB) - added by vaughnkoch 4 years ago.
Change to basehttp.py to time an HTTP query and display it in the dev server log.

Download all attachments as: .zip

Change History (10)

Changed 4 years ago by vaughnkoch

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

comment:1 Changed 4 years ago by vaughnkoch

  • Owner changed from nobody to vaughnkoch
  • Status changed from new to assigned

comment:2 Changed 4 years ago by vaughnkoch

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

comment:3 Changed 4 years ago by PaulM

  • Triage Stage changed from Unreviewed to Accepted

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.

comment:4 Changed 4 years ago by gabrielhurley

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

comment:5 Changed 4 years ago by PaulM

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.

comment:6 follow-up: Changed 4 years ago by 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...'

comment:7 in reply to: ↑ 6 Changed 4 years ago by vaughnkoch

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

comment:8 Changed 4 years ago by julien

  • Resolution set to wontfix
  • Severity set to Normal
  • Status changed from assigned to closed
  • Type set to Uncategorized

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.

comment:9 Changed 4 years ago by jacob

  • milestone 1.3 deleted

Milestone 1.3 deleted

Note: See TracTickets for help on using tickets.
Back to Top