Tracking Application Response Time with Nginx

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 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 format¹ with the three variables appended to it.

• request_time This shows how long Nginx dealt with the request
• upstream_response_time Gives us the time it took our upstream server (in this case Apache/mod_wsgi) to respond
• pipe Shows 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:

66.249.71.173 - - [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 /blog/2010/apr/30/installing-geodjango-dependencies-homebrew/ from 66.249.71.173 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.