April 08, 2010
You maintain a growing Rails application and you’re seeing something peculiar. Sometimes when you use the application, it feels like the performance deteriorates significantly. However, all of your performance data shows no issues – requests in the Rails log file look speedy, CPU utilization is fine, database performance is solid, etc.
At first, you wave it off as a fluke. But then a customer reports the same issue. Now you’re concerned.
You may be suffering from an under-provisioned Rails application – there are not enough instances of the web application server (Passenger, in many cases) to handle the requests. The requests wait in a queue outside of the Rails application – they won’t appear in the log file as slow requests.
A request that waits 15 seconds in the Passenger queue and takes 200ms in the Rails app shows up as a 200ms request in your Rails log. The queue time is hidden. It feels like a doctor appointment – an hour in the waiting room for a 5 minute checkup.
Luckily there is a cure, but it has side effects. When you have an under-provisioned Rails application you need more Passenger instances. It’s like adding more doctors to handle more patients. However, adding more Passenger instances costs memory. Absently increasing the maximum number of Passenger processes isn’t recommended. So, how do you know if throughput is an issue?
For starters, running
passenger-status will give you the number of sessions in each of the instance request queues. However, you don’t know how long they have been there. You may run
passenger-status once and see 0 sessions in the queue and 5 seconds later see several sessions in the queue.
In the end, we care about the total response time for users, not the queue length. Luckily, there is a fairly simple way to track this.
The graph above compares the Apache request duration vs. the Rails request duration. The Apache duration represents the total time processing the request on the server (time in queue + Rails processing). From the graph, it’s possible to see a couple of spikes in the queue time. Here’s an example of how the same request looks in a modified Apache access log and in Rails:
In order to track the request duration in Apache, the
%D directive must be used in the log format. Here’s a sample Apache log format that tracks duration in microseconds:
Take a look at our help entry for tracking Apache request duration. It’s pretty straight-forward.
Now that we’re tracking Apache request duration along with the Rails request times we can look for a couple of warning signs of an under-provisioned Rails application:
It’s great to start tracking Apache and Rails performance via log files, but it’s better when you can view the latest performance data in near real-time and look for the warning signs mentioned above. If you’re using Scout, you’ll get pretty graphs like the one earlier in this post. Additionally, you’ll get a nicely-formatted daily summary report for both Apache and Rails.
With Scout, just login to your account and install:
...and ensure that: