2007 / April 28^th/ Profiling your web application - the home-brew version

Have you ever wondered what the slowest part of your application was? Ever wished you could know that before you ship it off? I decided last night to take a crack at it for the upcoming redesign of poetry with meaning. I used a bit of scripting, a bit of Excel, and a whole-lotta fun with statistics.

What will you need?

• A Unix/OSX machine.
• httperf (free)
• Ruby
• A running instance of your web application

Getting started: httperf

I first learned about httperf through the excellent PeepCode and the benchmarking with httperf screencast. If you’re running Rails, I’d highly suggest checking out the screencasts — they’re well worth it. However, the method I’m showing today is language agnostic. While I use Ruby to perform some basic scripting, you could easily profile an application written in PHP, Python, or your language of choice.

httperf is a command line utility that performs requests to a web server and measures the time between requests. This allows you to get a maximum, minimum, average, and standard deviation of how many requests per second a particular server can serve up. Keep in mind this is a pretty CPU-intensive program, and ideally you are running it on a separate machine from the one the web server lives on.

A sample call to httperf looks like:

httperf --server poetrywithmeaning.dev --port 80 --uri / --num-conns 500

This sends 500 requests to http://poetrywithmeaning.dev/ The output looks like:

Maximum connect burst length: 1

Total: connections 500 requests 500 replies 500 test-duration 56.258 s

Connection rate: 8.9 conn/s (112.5 ms/conn, <=1 concurrent connections)
Connection time [ms]: min 38.7 avg 112.5 max 271.4 median 139.5 stddev 53.0
Connection time [ms]: connect 0.2
Connection length [replies/conn]: 1.000

Request rate: 8.9 req/s (112.5 ms/req)
Request size [B]: 72.0

**Reply rate [replies/s]: min 8.0 avg 8.9 max 10.4 stddev 0.7 (11 samples)**
Reply time [ms]: response 112.2 transfer 0.2
Reply size [B]: header 417.0 content 4996.0 footer 0.0 (total 5413.0)
**Reply status: 1xx=0 2xx=500 3xx=0 4xx=0 5xx=0**

CPU time [s]: user 12.04 system 43.00 (user 21.4% system 76.4% total 97.8%)
Net I/O: 47.6 KB/s (0.4*10^6 bps)

**Errors: total 0 client-timo 0 socket-timo 0 connrefused 0 connreset 0**
**Errors: fd-unavail 0 addrunavail 0 ftab-full 0 other 0**

I’ve flagged the lines (with **) that you need to take note of. The first is the Reply rate — this is the meat and potatoes, and the number we’ll use for all of our testing. The rest of the flagged lines are ones to take not of for errors. The 2nd flagged line tells us the reply status — we want these all to be 2xx or 3xx (2xx means a regular page, 3xx means a redirect). If you’re getting 4xx that’s most likely a 404 (file not found), and if you’re getting 5xx, that’s most likely a 500 (application error). The last two flagged lines show errors with httperf. If you’re getting anything other than 0 down here, either the machine running httperf or the machine running the application is dropping connections or erroring out.

Crawling multiple URLs

httperf is great at load-testing a singular URL, but what we really want to do is compare the relative speeds of different URLs of our application. So, you have a couple of options. You could always run the command-line client each time for all of these URLs… or you could write a script to do it for you. I chose the second route. Here’s a little ruby script I whipped up to go through a bunch of different URLS, and aggregate data into a tab-deliniated format.

#!/usr/local/bin/ruby
# command syntax:
# httperf --server poetrywithmeaning.dev --port 80 --uri / --num-conns 100

urls_to_test = [
  "/",
  "/poems",
  "/poems/filter/toprated",
  "/poems/filter/mostcomments",
  "/poems/filter/newcomments",
  "/poems/filter/posted",
  "/authors",
  "/users/filter/mostpoems",
  "/users/filter/newpoems",
  "/authors/enyaw/2381", #high volume poem
  "/authors/the-other-me/3939", # low volume poem
  "/authors/Fauxhemian", # high volume author
  "/authors/thex.rad", # low volume author  
  "/discussions",
  "/discuss/forum/1",
  "/discuss/topic/1",
  "/blog",
  "/blog/show/4019",
  "/blog/category/3",
  "/tools",
  "/rhyme/test"
]
number_of_connections_per_url = 500
server = “poetrywithmeaning.dev”
port = 3000

# create a log file
f = File.new(”performance.” + Time.now.year.to_s + ‘-’ + Time.now.month.to_s + ‘-’ + Time.now.day.to_s + “.log”, “w”)
final_output = “Log file for benchmarking \n\n”
final_output = final_output + “URL\tMin Req/s\tMax Req/s\tAverage Req/s\tStd Dev\n”

for url in urls_to_test
  percentage = 100*urls_to_test.index(url).to_i/urls_to_test.size.to_i
  puts (”%0.1f” % percentage).to_s + “%    Testing URL: ” + url
  output = `httperf –server #{server} –port #{port} –uri #{url} –num-conns #{number_of_connections_per_url}`
  if output =~ /Reply rate \[replies\/s\]: min ([0-9.]+) avg ([0-9.]+) max ([0-9.]+) stddev ([0-9.]+)/
    # add to our own log file
    final_output = final_output + “#{url}\t#{$1}\t#{$3}\t#{$2}\t#{$4}\n”
  end
end

f.write(final_output)
# close out the log file
f.close

• That regex for reply-rate was totally stolen from the script Geoffrey wrote in this screencast. The rest is hand-baked.

I saved this as httperfer.rb in my home directory, then just fired up terminal and typed in: ruby httperfer.rb While the script is running, it spits out some basic information about which URL it is testing and what % is complete. This is helpful since these kinds of tests can take very long depending on what quality of data you would like.

After all is said and done, a log file is created that has the minimum, maximum, average, and standard deviation reply rates for each of the urls tested in a tab-deliniated format — perfect for importing into Excel.

Visualizing the data

With a couple of calculations and inserting a simple graph, we get the chart below. Notice the colored section on top of each bar represents 2 standard deviations. You can search more about normal distributions to learn the meaning of this, but in a nutshell, it represents the error-range of the tests. You’ll notice some of the tests produced really bad data (such as /authors/the-other-me/3939). Always keep in mind the quality of your data.

What can we take away from this?

This kind of information is really interesting to me because it gives me relative speeds of different pages on my site. I can see what kind of information impacts performance. Some notes:

• It seems like the number of poems an author has makes a dramatic difference in the author view page. Compare /authors/Fauxhemian to /authors/thex.rad.
• On that same note, the author view page is by far the slowest page on the site.
• Forum & Topic views are surprisingly fast, as are Rhyme views (I expected rhyming to be much more CPU intensive).
• As expected, the poem/author filters are pretty resource-heavy.

Future benchmarking

Now that I’ve got this script written up, it’s easy for me to benchmark the entirety of my site as time goes on. I can measure performance increases due to caching or query optimization, and see what works best. At this point, running the script is cake — I just fire up mongrel on my Macbook Pro, fire up Ubuntu on the old PC and kick off my ruby script from Ubuntu and let it walk through.

Quick Recap

A quick recap for those of you lost as to what we did here:

1. Start your application server
2. Customize the httperfer.rb script for the URLs, server, port and number of connections to use.
3. Run ruby httperfer.rb
4. Let the process go through all URLs and collect data. Do not disturb the web server or the computer httperf is running on.
5. Import this data into Excel
6. Plotted the data into a bar-chart

Now have some fun benchmarking!

Name

Email (will not be published)

Website (optional)