Our site has some pages that can take a while to return. The fact of them is probably, in the short to medium term, inevitable, and in general performance is good. Anecdotally though, users and testers have been experiencing poor performance on pages that we know should render quickly or even instantly (because they’re cached). What is going on?
Setup: Apache, mongrel, RoR
Our main site setup is extremely straightforward: We use Apache and mod_proxy_balancer to field incoming requests, which are then farmed out to a group of Mongrel instances that run our Ruby on Rails application.
Mongrel queues requests and is effectively single-threaded with reference to Rails
Mongrel is multi-threaded, but it locks a mutex as soon as it starts Rails processing. The result for most of us is that it processes one request at a time, potentially with a queue of pending requests on the front. If a request is taking a long time, anything queued up behind it, no matter how trivial, waits. Our pack of Mongrels should be big enough to avoid this situation with the sorts of traffic we get presently, but is it?
Apache’s load balancer
Apache’s mod_proxy comes with two different load balancing methods: “byrequest” (the default) and “bytraffic”. Both of these are historical balancers: they will ensure that cumulative load is distrubuted evenly between workers, but they don’t particularly care what the current state of a given worker might be. It seems entirely possible that Apache could assign a request hitting a poorly-performed page to worker A, sprinkle short-lived requests to its friends B and C, then assign another request to A because it’s A’s turn – even though A is still busy and B and C are both idle. And so on.
This would certainly explain “fast” pages sometimes coming back really slowly, and the overall server load wouldn’t even have to be very high.
What are our mongrels actually doing?
Mongrel’s logging and debugging output are not terribly helpful out of the box, at least not for finding out what’s going on with queued requests. Fortunately, the truly awesome proctitle will tell us exactly what we want to know, right there in the output of ps. It’s almost as if other people have had this problem before…
Drop the plugin into Rails, restart the mongrels, and let’s spectate a while.
joel@hiscomputer: $ watch -n 0 'ps ax | grep mongrel' # real-time and everything 
17209 ? R 18:22 mongrel_rails [9001/2/1524]: handling 127.0.0.1: GET /reviews/mpn/take_2/tt45920
17213 ? R 14:25 mongrel_rails [9002/1/1321]: handling 127.0.0.1: GET /reviews/mpn/humax/lu23_td2
17217 ? R 14:50 mongrel_rails [9003/1/1190]: handling 127.0.0.1: GET /reviews/mpn/navman/s30
17221 ? S 12:11 mongrel_rails [9005/0/1032]: idle
Brilliant – the interesting bits on the first line are the ‘2’, telling us that the Mongrel on port 9001 has two requests to serve (one active and one queued), and that it’s currently serving a reviews page for Grand Theft Auto IV. Already we can see that Apache has given the 9001 Mongrel a request when it was doing something else, even though the 9005 Mongrel could have served it faster.
So, our hypothetical scenario is a real one, but how bad does it get? And how much of it is down to unhelpful load-balancing?
Digression: Siege
We use a number of different tools to automate web traffic for testing purposes. Our current favourite back-of-the-napkin number-generator is Siege.
Siege will take a list of URLs and happily blast away at them at a rate and concurrency, and for a duration, that can be tweaked in arbitrary ways to explore different aspects of server performance. In this case we want to see a wide variety of requests, and to squish them temporally to see just how unevenly individual Mongrels end up getting loaded. Since we suspect that live users are hitting this problem, we can just take the request URLs from a day’s worth of our live Apache logs. Something like:
joel@hisproductionserver$ cut -d -f 7 /var/log/httpd/access.log | perl -p -e 's{^}{http://testserver}' > urls.txt
On my current test box, I have eight Mongrels running. I start with eight concurrent siege users in my .siegerc file, a two-minute siege duration, the urls.txt file generate a moment ago, and with proctitle I see this:
13776 ? Rl 0:17 mongrel_rails [9000/4/17]: handling 127.0.0.1: GET /reviews/mpn/stoves/600sidlm
13779 ? Sl 0:04 mongrel_rails [9001/0/20]: idle
13782 ? Sl 0:05 mongrel_rails [9002/1/19]: handling 127.0.0.1: GET /reviews/mpn/sharp/lc20s5ebk
13785 ? Rl 0:17 mongrel_rails [9003/1/18]: handling 127.0.0.1: GET /reviews/mpn/stoves/600sidlm
13789 ? Rl 0:15 mongrel_rails [9004/3/17]: handling 127.0.0.1: GET /reviews/mpn/sharp/lc20s5ewh
13793 ? Rl 0:13 mongrel_rails [9005/2/17]: handling 127.0.0.1: GET /browse/product_type/routers
13796 ? Sl 0:12 mongrel_rails [9006/0/18]: idle
13800 ? Sl 0:12 mongrel_rails [9007/0/18]: idle
We can see that Apache is distributing the load fairly evenly over time (the ‘17’ in ‘[9000/4/17]’), but is doing badly at making sure that load is distributed evenly at any given moment. The 9000 server has 4 pending requests, while 9001, 9006 and 9007 are sitting idle. There are a fairly low number of concurrent users, and already half of them are having an unnecessarily bad time!
Monit as a way of taking snapshots
Like a lot of people, we use monit to make sure our servers are up, and to kick them when they’re down so they get up again. It can be configured to kill and restart Mongrel processes that take more than some number of seconds to respond, but we can repurpose it to take snapshots of ps output and append them to a file instead using a Very Small Shell Script – the camera instead of the elephant gun, if you like. proctitle is just so handy.
Each of our Mongrels has a .monitrc entry that looks like this:
if failed port 9001 protocol http # check for response
with timeout 5 seconds
then exec /home/joel/bin/slow_request.sh 9001
where, if a server takes more than five seconds to respond, slow_requests.sh simply locates the process ID of the Mongrel running on port 9001, and records the output of ps for that process. The results were very suggestive – right at the top, we see lines like this:
17213 ? S 27:27 mongrel_rails [9002/4/2451]: handling 127.0.0.1: GET /reviews/mpn/henry/numatic
1148 ? S 2:48 mongrel_rails [9000/10/240]: handling 127.0.0.1: GET /search
1148 ? S 3:32 mongrel_rails [9000/5/314]: handling 127.0.0.1: GET /
and even
2955 ? S 11:41 mongrel_rails [9001/17/1010]: handling 127.0.0.1: GET /browse/product_type/Tents
At one point, a single long-running process had managed to force sixteen other site vistors’ requests to wait!
There are quite a few lines (after the server had been monitoring for a while) that were unlike these examples – specifically, they each showed only a single pending request, and it wasn’t necessarily for a slow page. Often, in fact, it would be a request for the front page, which should be quick in the first instance, and cached to within an inch of its life in the second. Performance appears to be degrading over time. We’ll look at that later, because a solution to our uneven load balancing problem has suggested itself.
bybusy mod
Out of the box, Apache offers the two load balancing methods I noted earlier. Being Apache, you can bet that they will have made it fairly easy to add more. And indeed, this turns out to be the case. We added a third “bybusy” lbmethod, able to be configured in the same way as the others. It was initially very simple – for each proxy worker thread in the web server, increment a “busy” counter when assigning a request to that worker. In the post-request hook, decrement the counter again. When choosing a worker, simply pick the worker with the lowest “busy” value.
Simple to say, and thanks to the general cleanliness and friendliness of the Apache code base, simple to do. Attacking it with Siege resulted in exactly what one would hope for: Mongrels absorbed load evenly even when concurrent requests greatly outnumbered the available workers, and most importantly there was never a case where an incoming request was assigned to a Mongrel that was already doing something while another sat idle.
Refinement
This is more of a nicety than anything else, but it would be nice to know that grabbing a random Mongrel’s log for period X will give me a representative sample of what’s been going on across all of them. As it stands, the bybusy method will, over time, favour Mongrels higher up the load-balancer’s list. A little reflection will show that if traffic is sparse, then this inequity gets much worse.
We ended up refining bybusy a little, by using the “byrequest” method as a tie-breaker between workers with identical “busy” values (most frequently, when they are idle). So we get the moment-to-moment balancing we wanted to start with, but also the cumulative balancing that we had originally and which leads to nicely-balanced log files. A small thing, I know, and Mongrels don’t get tired, but it seemed like a good idea.
UPDATE: This has been submitted as a patch to httpd, for source and progress go to Apache Bugzilla.
