How I profile my Nginx + proxy pass server

16 February 2011   3 comments   Python, Web development

Powered by Fusion×

Like so many others you probably have an Nginx server sitting in front of your application server (Django, Zope, Rails). The Nginx server serves static files right off the filesystem and when it doesn't do that it proxy passes the request on to the backend. You might be using proxy_pass, uwsgi or fastcgi_pass or at least something very similar. Most likely you have an Nginx site configure something like this:

server {
   access_log /var/log/nginx/mysite.access.log;
   location ^~ /static/ {
       root /var/lib/webapp;
       access_log off;
   location / {
       proxy_pass http://localhost:8000;

What I do is that I add an access log directive that times every request. This makes it possible to know how long every non-trivial request takes for the backend to complete:

server {
   log_format timed_combined '$remote_addr - $remote_user [$time_local]  ' 
                             '"$request" $status $body_bytes_sent '
                             '"$http_referer" "$http_user_agent" $request_time';
   access_log /var/log/nginx/timed.mysite.access.log timed_combined;

   location ^~ /css/ {
       root /var/lib/webapp/static;
       access_log off;
   location / {
       proxy_pass http://localhost:8000;

If you do that your access log file will look the same as before except now it will have a last column that contains the timing. Now, let your site spin for a couple of days/weeks/months and later download the access log:

$ rsync -avzP .

Excellent, now download this script and save it next to your log file. When you run it you get a nice little menu that should be sufficiently self-explanatory:

$ python timed.mysite.access.log
What do you want to know?

     1) Slowest performer
     2) Most common
     3) Total cumulative time

The most interesting one is probably the last one because that's where most time is spent by your web application and perhaps that's the place to start if you want to make your site faster or if you want to know what is most important in terms of test coverage. Here's a sample output from my on the "Total cumulative time":

537.582    /?replypath=/comment-20041222-x54i/comment-20041231-0gug
519.277    /?replypath=/comment-20041222-x54i
306.039    /
259.845    /rss.xml?oc=Django
251.064    /Bush-country/
233.165    /plog/blogitem-040601-1
224.459    /plog/blogitem-040601-1/?replypath=/c0610287425
186.032    /plog/interior-octopus/octopus.jpg?display=large
170.430    /plog/blogitem-040601-1/?replypath=/comment-20050714-12mf
182.964    /plog/button-tag-in-IE
65.311     /plog/unicode-to-ascii
30.086     /plog/blogitem-040406-1/compressor
7.581      /plog/blogitem-040806-1/test-printsql
1.676      /gkc/callback
0.372      /plog/blogitem-040404-1/getCommentCookie
0.364      /plog/donecal-homepage-10k-req-per-sec/manage_editKeywords
0.363      /plog/blogitem-040627-1/previewComment
0.274      /plog/createelement-a
0.246      /plog/blogitem-20031027-2106/previewComment

I hope it helps. Perhaps other people can help me improve the script and later we can turn it into a package. One thing I would like to see for example is to use the median to reduce crazy spikes (e.g. a URL that normally takes 10 milliseconds just once takes 10 seconds)


Aldrin Leal
You missed the "$" in request_time, obviously. I just discovered after running for one week hehe
Peter Bengtsson
Thanks for noticing. Fixed now.
It seems that the link to the script does not work anymore.
Thank you for posting a comment

Your email will never ever be published

Related posts

DoneCal homepage now able to do 10,000 requests/second 13 February 2011
Nice testimonial about django-static 21 February 2011
Related by keywords:
fcgi vs. gunicorn vs. uWSGI 09 April 2010
Is Nginx obsolete now that we have Amazon CloudFront? 28 July 2012
How I stopped worrying about IO blocking Tornado 18 September 2012
The awesomest way possible to serve your static stuff in Django with Nginx 24 March 2010
How to uninstall nginx with apt 28 March 2008
How much faster is Nginx+gunicorn than Apache+mod_wsgi? 22 March 2012
Local Django development with Nginx 11 October 2010
Getting uploadify to work 17 July 2009
What makes my website slow? DNS 23 October 2009
ssl_session_cache in Nginx and the ab benchmark 31 December 2010
Secs sell! How frickin' fast this site is! (server side) 05 April 2012
My first YSlow Grade A (100)! 17 December 2008