Recently we noticed some intermittent slow downs with our Gondola sites and wanted to track down the source of the issue. Our sites are all Django projects served by Apache/mod_wsgi behind an Nginx frontend proxy. Nginx’s upstream module makes the process of logging response times trivial with its upstream_response_time variable.
I added this block to
/etc/nginx/nginx.conf to define a new log format
timed_combined which captures some additional data in our logs:
log_format timed_combined '$remote_addr - $remote_user [$time_local] ' '"$request" $status $body_bytes_sent ' '"$http_referer" "$http_user_agent" ' '$request_time $upstream_response_time $pipe';
This is the default
combined format1 with the three variables appended to it.
request_timeThis shows how long Nginx dealt with the request
upstream_response_timeGives us the time it took our upstream server (in this case Apache/mod_wsgi) to respond
pipeShows 'p’ in case the request was pipelined.
Next we modify our
access_log directives to use the new format:
access_log /var/log/nginx/yourdomain.com.access.log timed_combined;
Here’s an example of the log output:
18.104.22.168 - - [08/Nov/2010:14:16:18 -0600] "GET /blog/2010/apr/30/installing-geodjango-dependencies-homebrew/ HTTP/1.1" 200 6569 "-" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)" 0.640 0.640 .
In other words, the Googlebot spidered our blog post at
22.214.171.124 at 2:16pm. It took 0.640 seconds to serve (all of those came waiting for the upstream proxy) and the request was not pipelined.
Some clever log filtering can now show you exactly where and when your Django stack is slowing down, giving you clues about where to start optimizing. In addition, Nginx’s logging can be used to capture all sorts of interesting information such as cookies, http headers etc. You’ll find documentation of the core variables here and other modules spread throughout the rest of the docs.