How to Show Response Time in a Rails Page with Mongrel

You’ve seen this on Google result pages, right?

You wanna do that in your Rails app that runs with Mongrel? I show you how. Sit down. And along the way I’ll show what I learned about writing custom Mongrel HttpHandlers and why you shouldn’t store instance variable in them.

I remember seeing it there long ago when Google was new. I liked it because:

  1. Faster is better
  2. It shows Google focuses on helping me go fast
  3. It reminds the Google developers to focus on helping me go fast

So I’m developing this awesome web site now and I’m using Ruby on Rails with Mongrel. I wanted to pull a Google and show the server response time as text content in my pages, as a reminder to myself and my co-developer that it’s super-important to keep things fast.

I can haz question

How do you put response time in a page using Rails?

So I did some research. My first inclination was to create an around_filter in my ApplicationController. In fact the documentation for ActionController::Filters even uses a BenchmarkingFilter as an example.

But if I put a filter there what would it benchmark? Just the time spent in the controller and view? But what about the time spent in Rails outside my controller and my view? I want a benchmark that’s higher up the chain, kinda close to where the request is received and the response is sent back, so the time displayed in the page gives a truer picture of how long it took to handle the request.

More importantly: let’s say my server gets backed up with a queue of requesteses (through my amazing connections I get on the Yahoo! home page and there are more simultaneous requests than I have request handlers). I’d like to profile the total time from when each request first came on board until I said buh-bye to the response. If I use an around_filter I’m not including a crucial piece of the response time: how long my user waited in line before even entering Rails because my server was serving someone else first.

If you’re at the ball game and you go get a hot dog and there are 30 people in front of you in line, are you excited that it takes only 1 minute to serve each person? Hell no. You’ll be there 31 minutes, including the time to serve you. You’ll miss two innings and the game-winning homer by Mr. Steroid. 31 minutes is the response time that matters because that’s how long the customer is waiting.

Plus you know you always get stuck in the slow line so it’s more like 50 minutes.

So that’s when I realized that I was asking the wrong question. The question isn’t how do you put response time in a page using Rails.

The question I shoulda had

How do you put response time in a page using Mongrel?

Mongrel sits higher up the food chain than Rails. It’s the little servy thing that doles out HTTP requests to ActionController.

I did a little digging and found that Mongrel has something called handlers, also known as filters.

Handlers are how Mongrel handles requests. When Mongrel gets a request it runs through all its handlers, passing the request to each one. (It calls them all; by default it doesn’t stop when one of them handles the request.) Handlers are not just for extensibility–they’re the way Mongrel works. There’s a RailsHandler that comes with Mongrel. That’s the one that passes requests off to Rails. There’s also a DirHandler. In a Rails app it uses that one to handle requests for files in the public/ folder. There are other handlers for other things. Like a CampingHandler for Why the Lucky Stiff’s Camping.

Each handler has a process method that Mongrel calls to process requests.

Each handler also has an optional request_begins method. For each request Mongrel calls the request_begins methods in all the handlers first, then it calls the process methods in all the handlers.

But here’s the sweet part. Rails may be single-threaded but Mongrel ain’t. Mongrel calls request_begins on all the HttpHandlers the moment it sees a new request. This happens in a separate thread from the one that’s currently processing a request in Rails (or some other handler), so it does not even have to wait for the current customer to be served before starting the timer on the newly added customer.

Go doggy. The stopwatch starts as soon as someone gets added to the back of the line.

By the way, Mongrel won’t call request_begins unless you tell it to. Here’s how you tell it to. Put this inside your subclass of HttpHandler:

  def initialize(options={})
    @request_notify = true
  end

Cool. I can create a new BenchmarkFilter class a subclass of HttpHandler. I check the time in its request_begins method–which gets called before any of the process methods (including the RailsHandler’s one)–and check the time again in the process method for my handler. Mine will get called after the Rails one if I install it at the end.

class BenchmarkFilter < HttpHandler
  def request_begins(params)
    # stuff goes here
  end

  def process(request, response)
    # and here
  end
end

Technically my filter won’t be called quite early enough because some other filters might be called first, and some other “process” methods might be called later. But I’m not going to stress over that.

About those nasty instance variables

The natural thing to do is store the start time in an @instance variable or maybe a @@class variable but I discovered this doesn’t work well in HttpHandlers. For performance reasons Mongrel only creates a single instance of your HttpHandler subclass instead of creating a new instance for each request. So using an instance variable is the same as using a class variable. Not only that but remember I said Mongrel is multi-threaded? That means your one HttpHandler instance will be called simultanously on lots o’ threads. Start reading and writing instance variables and you’re asking for a quick trip to the happy laughy farm.

(The @request_notify variable above is ok because we set it once during initialization–before all the thread craziness starts–and never change it.)

I also noticed in my testing that sometimes the request_begins methods were getting called several times in a row before the process methods for the same requests. Again that’s because it’s multi-threaded. But just think how it messes with your instance variables. Even if you guard the reads and writes with a Mutex, your start times would get all mixed up because you’re keeping track of a bunch of simultanous start times in a single variable.

When Mongrel calls request_begins the only parameter it passes in is the request parameters. It doesn’t even pass the request because the request hasn’t finished initializing yet. I needed a way to associate the start time with the request and pull it out later so I could see how much time elapsed. Since the parameters passed to request_begins are a reference to the request’s @params variable, any changes made to the parameters will be carried along with the request. So here’s what I did:

  # Define a const for performance
  HANDLER_START_TIME = "X-Handler-Start-Time".freeze

  def request_begins(params)
    params[HANDLER_START_TIME] = Time.now
  end

This code adds a custom key to the parameters hash, and in the value it stores the start time. As the comment mentions, I froze the name of the handler to get slightly better performance. I stole that trick from the Mongrel source code.

Later on, when my process method is called with the request as one of the parameters, I can pull the start time out of request.params:

  def process(request, response)
    elapsed_time = Time.now -
      request.params[HANDLER_START_TIME]
    # I'll add more in a sec
  end

You put the time in the coconut

The next question: how do I put the time in the content of a page? The page has already been rendered by the time my handler gets called, so I can’t set an @elapsed_time variable and render it in my view.

Here’s the approach I took: in my views I output a string of characters that the BenchmarkFilter looks for. If it finds those characters it replace them with the elapsed time. If not, it does nothing.

I wanted it also to have no effect at all if it’s running without the BenchmarkFilter handler. Let me rephrase that with lots of negatives for clarity: I didn’t want it not to have no effect if it didn’t run without having no BenchmarkFilter handler.

My first idea was to create a partial file called _response_time.html.erb in a “shared” folder. The partial’s contents are:

<span id="response_time"><span>

In the handler I look for this in the response string and replace it with something like:

<span id="response_time">(0.15 seconds)<span>

Wherever I want to show the response time in a page I do this:

<%= render :partial => "shared/response_time" %>

If you want to put the output in an HTML comment you can do that too, so it’s not shown on the page but can be inspected by looking at the source.

Why no worky?

I ran it and it seemed to work. Most of the time. But it was cranky. Sometimes it worked and sometimes not. I debugged it and noticed why. Do you know? See if you can guess from these hints:

Hint #1

The HTTP headers had already been rendered. (By the RailsHandler) before my handler is called. Think before you go to hint #2.

Hint #2

One of the HTTP headers is called Content-Length.

Hint #3

I was changing the length of the content without changing the Content-Length header.

As the voice in the “create a weblog in 15 minutes” video would say: “wup!”

Kevin Spacey * 15

I started down the path of trying to fix the Content-Length header on the fly but that got frustrating so I tried something easier: change my partial so it outputs exactly the same number of characters whether the BenchmarkFilter class replaces it or not.

I decided to format my output like this:

  (0.15 seconds)

That takes 14 characters. Add another one in case it’s 10.00 seconds or more (yikes) to make 15. So I changed the span in the partial to have 15 spaces in it:

  <span id="response_time">               </span>

Then I wrote the BenchmarkFilter code so it always uses 15 characters. If it’s <9.99 seconds I insert an extra space between the number and the word “seconds.” The browser eats that space anyway so it looks fine. And if it’s >99.99 seconds, God forbid, I just output “(>100  secs)” (again there’s an extra space in there to make it 15 chars), which looks like “(>100 secs)” in the page.

Handling RJS responses

I decided I also wanted to update the response time partial when executing an RJS response. Here’s how the RJS looks:

page.replace "response_time",
  '<span id="response_time">               </span>'

(This works but I’m not happy with it. I shouldn’t repeat the special string. I really ought to move this to a constant in the application helper.)

With an RJS the HTTP Handler sees JavaScript, not HTML, in the response. So instead of:

<span id="response_time">               </span>

the output has all the special characters quoted, so the handler has to search for:

\74span id=\\"response_time\\"\76               \74/span\76

I also noticed that on newer versions of Rails, at least on my friend’s Mac, the response was in Unicode:

\\u003Cspan id=\\"response_time\\"\\u003E               \\u003C/span\\u003E

Anyway, if you want to see the hairy details you can look at the code.

Installing the handler

If you want to run Mongrel and tell it to execute a particular Ruby file at startup, one way is to use mongrel_rails with the -S option:

mongrel_rails start -S lib/http_handlers/benchmark_filter.rb

(I decided to put the handler file in lib/http_handlers).

At the end of the file, after closing out the class, you have to call the “uri” function to tell Mongrel to install the handler:

# This calls Mongrel::Configurator::uri.  The first
# argument is a prefix.  Passing "/" means we want
# this handler to be executed for all requests.
uri "/", :handler => BenchmarkFilter.new

How it looks

So you want to see what the output looks like? Here’s a picture:

Ta-da!

Obviously this won’t work with other servers than Mongrel, so if you want to support any HTTP server you’ll have to figure out another technique or use an around_filter and lose the waiting-in-the-queue time in the output.

And it won’t work with static pages that you cache in something like nginx.

You can download the code here. Feel free to customize it. But remember: don’t change the string length when doing the substitution.

4/11/09 Update: Rack

Now that Rack is on the scene, it wouldn’t be too hard to rewrite this thing to work with any web server, including Phusion Passenger.

But I haven’t rewritten it. If you feel like rewriting it, go for it–and then post a comment below so people can find it.

About these ads

8 Responses to “How to Show Response Time in a Rails Page with Mongrel”

  1. hemanth Says:

    hi Brian,

    i tried to access the rails ROOT_PATH from inside the BenchmarkFilter class
    but its returning the handler.rb’s path.

    how should i get the rails ROOT_PATH.

    HEMANTH

  2. Brian Morearty Says:

    Hemanth,

    I don’t know of a way to access the Rails ROOT_PATH from inside the BenchmarkFilter class because BenchmarkFilter is a Mongrel filter so it’s one level above Rails. It’s not running inside Rails so it doesn’t have access to the Rails environment.

    The RailsHandler class, which is part of Mongrel, is what passes requests on to Rails. Maybe if you take a close look at that class you’ll find an answer to your question.

  3. phx Says:

    Hey Brian, thanks for your post, im looking for this feature for a while, but have a few questions.

    Where should i put the benchmark_filter.rb?
    (In the Rails App Lib Folder or in the Mongrel Lib Folder?)
    Im using NetBeans 6.1.

    Sorry, but im really new to the whole rails stuff.

  4. Brian Morearty Says:

    Good question, phx. I’m not sure if there’s an “approved” place to put Mongrel filters. I placed it in a subfolder I called http_handlers in my Rails lib folder. Not in the Mongrel lib folder.

  5. phx Says:

    Thanks for your reply!

    I just created the http_handlers folder and drop the benchmark_filter.rb into it, without success :)

    But i suppose that my parameters: “-S lib/http_handlers/benchmark_filter.rb” are not at the right place for the NetBeans build-in Mongrel Server.

    I googled this wiki entry: http://wiki.netbeans.org/FaqRailsMongrel and write ARGV+=%w(mongrel_rails start -S lib/http_handlers/benchmark_filter.rb) at the end of scripts/server File, but still not working.

  6. hemanth Says:

    Brian,

    thanks a lot Brian.

  7. Brian Morearty Says:

    phx, I just realized that when you said “I’m using NetBeans” you meant you are trying to get the response time to show when running Mongrel from within NetBeans. I have not yet tried doing that, although I agree it would be nice to do.

    What I’ve gotten working is running mongrel_rails from the command line.

    When I run from within NetBeans I don’t get to see the response time on my pages. If you do figure out how to do that, it would be nice if you could post the solution as a comment here for others to see. From what I’ve seen so far of NetBeans’ Rails integration, it looks like it doesn’t currently have the flexibility to override how it runs the server.

  8. phx Says:

    Hey Brian,

    i come to the same conclusion as you. Seems not to be working right now with NetBeans 6.1.

    Perhaps somebody else figure out an soloution.

    I keep watching the comments :)

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s


Follow

Get every new post delivered to your Inbox.

%d bloggers like this: