OnRails.org

I’ve recently upgraded to OS X 10.5 (Leopard), and all-in-all, I’m pleased with the experience. My biggest issue has been the default stacks behavior—the icon changes to the last thing added to the stack, making visual identification unnecessarily cumbersome. I worked around this annoyance (as outlined here) by changing the sort to name rather than date added, and adding a dummy folder named “_1” that will sort to the top. For extra bonus points, I customized the icon of the dummy folder. For some yet unknown reason, the most recently downloaded item still peeks through from time to time, but it’s much better than before.

Maybe it’s my Windows history showing through, but I went with the “clean-sweep” erase and install method. For a non-developer, I’d probably recommend the upgrade (and in fact I used that method for my Father-in-law’s MacBook), but I had lots of custom bits scattered about my machine, and didn’t want to be chasing any incompatibility gremlins.

So now, to get my development environment set up on the new machine… Leopard includes a fairly complete Rails stack out of the box, with a non-broken Ruby, readline support, and most of the commonly used gems. Read more here.

MySQL was not included, but the latest installer (mysql-5.0.45-osx10.4-i686.dmg) for 10.4 from dev.mysql.com downloads worked (mostly) fine. The Server and the StartupItem install and operate correctly. The PrefPane installs, but does not appear to actually do … anything. I’ll have to work on that, but I can live without it for now. After a bit of manual hacking on my database dump file from Tiger (where I was running a 5.1.x beta of MySQL), all my databases are back in place.

One last piece that I needed for my Rails apps—RMagick. I know it’s possible to install RMagick and its dependencies, um, “autoRMagickally” via a package management system like MacPorts or Fink, but I prefer not to. For some background on why not, you can read this article at hivelogic. The last time I was rebuilding my laptop and desktop near the same time, I put together a shell script to automate the process of installing RMagick. I got it back out and dusted off the cobwebs, and voila! RMagick on Leopard. (note: replace wget with “curl -O”, if you don’t have wget installed on your machine) Here’s the code:

#!/bin/sh
wget http://download.savannah.gnu.org/releases/freetype/freetype-2.3.5.tar.gz
tar xzvf freetype-2.3.5.tar.gz
cd freetype-2.3.5
./configure --prefix=/usr/local
make
sudo make install
cd ..

wget http://superb-west.dl.sourceforge.net/sourceforge/libpng/libpng-1.2.22.tar.bz2
tar jxvf libpng-1.2.22.tar.bz2
cd libpng-1.2.22
./configure --prefix=/usr/local
make
sudo make install
cd ..

wget ftp://ftp.uu.net/graphics/jpeg/jpegsrc.v6b.tar.gz
tar xzvf jpegsrc.v6b.tar.gz
cd jpeg-6b
ln -s `which glibtool` ./libtool
export MACOSX_DEPLOYMENT_TARGET=10.5
./configure --enable-shared --prefix=/usr/local
make
sudo make install
cd ..

wget ftp://ftp.remotesensing.org/libtiff/tiff-3.8.2.tar.gz
tar xzvf tiff-3.8.2.tar.gz
cd tiff-3.8.2
./configure --prefix=/usr/local
make
sudo make install
cd ..

wget http://jaist.dl.sourceforge.net/sourceforge/wvware/libwmf-0.2.8.4.tar.gz
tar xzvf libwmf-0.2.8.4.tar.gz
cd libwmf-0.2.8.4
make clean
./configure
make
sudo make install
cd ..

wget http://www.littlecms.com/lcms-1.17.tar.gz
tar xzvf lcms-1.17.tar.gz
cd lcms-1.17
make clean
./configure
make
sudo make install
cd ..

wget ftp://mirror.cs.wisc.edu/pub/mirrors/ghost/GPL/gs860/ghostscript-8.60.tar.gz
tar zxvf ghostscript-8.60.tar.gz
cd ghostscript-8.60/
./configure  --prefix=/usr/local
make
sudo make install
cd ..

wget ftp://mirror.cs.wisc.edu/pub/mirrors/ghost/GPL/current/ghostscript-fonts-std-8.11.tar.gz
tar zxvf ghostscript-fonts-std-8.11.tar.gz
sudo mv fonts /usr/local/share/ghostscript

wget http://imagemagick.site2nd.org/imagemagick/ImageMagick-6.3.5-9.tar.gz
tar xzvf ImageMagick-6.3.5-9.tar.gz
cd ImageMagick-6.3.5
export CPPFLAGS=-I/usr/local/include
export LDFLAGS=-L/usr/local/lib
./configure --prefix=/usr/local --disable-static --with-modules --without-perl --without-magick-plus-plus --with-quantum-depth=8 --with-gs-font-dir=/usr/local/share/ghostscript/fonts
make
sudo make install
cd ..

sudo gem install RMagick

Rails makes things easy on developers—maybe too easy. It’s not uncommon to reference an association while iterating over a collection of objects, resulting in a performance-devouring N+1 queries being executed. Of course, this is easily fixed with eager loading of the association, but you get my point. Rails can be a big gun, and it’s easy to blow off your foot.

Once your application is moved into production, it becomes important to keep an eye on performance over time in order to get a feel for trends and plan capacity intelligently. Numerous Rails performance measuring tools exist, but I find that it helps to correlate performance of your application with simultaneous lower-level performance metrics of your system (CPU and Memory usage, Load Average, etc). Besides that, hey! Pretty Graphs! Enter munin, an open-source, extensible monitoring tool with a number of out-of-the-box plugins that are useful to SysAdmin type folks. There’s a pretty decent (though brief) writeup on howtoforge that explains a bit more about how to go about getting your own munin. Go ahead and check it out—I’ll chill here until you’re back.

That wasn’t too bad, huh? Okay, so at this point you should have a working munin instance. It will take a few minutes of data collection before your graphs look like anything, but going forward, you’ll have historical graphs of several key metrics for managing your server(s). It’s outside the scope of this article, but you can also set up munin to monitor multiple servers on your network, and/or alert you when critical threshold levels are passed.

Well, knowing CPU usage is great, but it would also be nice to have some idea what the average user experience is like on your site. Does your Rails app perform differently at different times of day? How long does it typically take for your app to render a page? Is the majority of the time spent in the database, or rendering? Is the response time about the same between production deployment versions? I wanted answers to these questions too, so I came up with a small ruby program that watches your Rails log in realtime, and when munin asks, provides summary information about the performance of your application. Below, I’ll go over the code section by section; for those who want it now, scroll to the bottom of the article to find the download link.

The basis of the solution is a Ruby array: we stuff values into it, then compute the average of all the values and clear the array each time munin pings us. Every time a value is added, we also check it against the maximum already seen, so we can report the maximum response time in addition to the average. We keep three of these objects around, one each for DB, Rendering, and Total response times. There is also a mode that lets you look at the current value without consuming it—useful for peeking inside without affecting the data that munin will ultimately see. Here’s the class that implements this functionality:

class Accumulator
  def initialize
    @values = Array.new()
    @max = 0
  end

  def add(value)
    @values << value
    @max = value if value > @max
  end

  def average(read_only=false)
    return_value = if @values.length == 0
      nil
    else
      @values.inject(0) {|sum,value| sum + value } / @values.length
    end
    @values = Array.new() unless read_only

    return_value
  end

  def max(read_only=false)
    return_value = @max
    @max = 0 unless read_only
    return_value
  end
end

In the next section of the code, we build our accumulators, and begin tailing the logfile to extract performance numbers. This requires the file-tail gem, available from rubyforge. Note that in my setup, this file resides in a subdirectory under lib in RAILS_ROOT. If you choose to place this file elsewhere, you’ll have to adjust the path to the logfile accordingly. Another thing to note: in our environment, the load balancer continually pings a “heartbeat” action on each node to make sure it is still responsive. As we will be hitting this action repeatedly, it is engineered to be as lightweight as possible. Therefore, any numbers from it are pretty meaningless to our overall statistics, so we don’t want to include them. To keep these numbers from skewing our results, we define an IGNORE_PATTERNS regexp (earlier in the code). If the request matches a pattern we want to ignore, its statistics are not collected.

LOGFILE = File.join(File.dirname(__FILE__), '..', '..', 'log', "#{RAILS_ENV}.log")
$response_data = { :total     => Accumulator.new(),
                   :rendering => Accumulator.new(),
                   :db        => Accumulator.new() }

Thread.abort_on_exception = true
logtail = Thread.new do
  File::Tail::Logfile.tail(LOGFILE) do |line|
    if line =~ /^Completed in /
      parts = line.split(/\s+\|\s+/)
      resp = parts.pop
      requested_url = resp[/http:\/\/[^\]]*/]
      next if requested_url =~ IGNORE_PATTERNS

      parts.each do |part|
        part.gsub!(/Completed in/, "total")
        type, time, pct = part.split(/\s+/)
        type = type.gsub(/:/,'').downcase.to_sym

        $response_data[type].add(time.to_f)
      end
    end
  end
end

So now we have a thread busy gathering our data—how can we expose the data to a munin plugin? There are multiple ways to do this, but I chose to use a small HTTP server listening to requests from the local machine only. We could build such a thing in Rails, but we really don’t need about 90% of the features Rails has to offer. Since we’re running Rails as a Mongrel cluster, we already have a perfect tool at our disposal for writing small HTTP request handlers in Ruby: Mongrel. Here are a couple of pages about how to get started writing Mongrel handlers—it’s pretty straightforward. Here’s our handler:

class ResponseTimeHandler < Mongrel::HttpHandler
  def initialize(method)
    @method = method
  end

  def process(request, response)
    response.start(200) do |head,out|
      debug = Mongrel::HttpRequest.query_parse(request.params["QUERY_STRING"]).has_key? "debug"
      head["Content-Type"] = "text/plain"
      output = $response_data.map do |k,v|
        value = v.send(@method, debug)
        formatted = value.nil? ? 'U' : sprintf('%.5f', value)

        "#{k}.value #{formatted}"
      end.join("\n")
      output << "\n"
      out.write output
    end
  end
end

h = Mongrel::HttpServer.new("127.0.0.1", PORT)
h.register("/avg_response_time", ResponseTimeHandler.new(:average))
h.register("/max_response_time", ResponseTimeHandler.new(:max))
h.run.join

The handler is generic so that it can call an arbitrary method on our collection of data arrays, so we can set up one URI for the average, and one for the maximum. With this in place, we can write a simple munin plugin script that uses Net::HTTP to query our Mongrel to get at the performance data.

Basically, a munin plugin has two usage scenarios. When called with the single argument “config”, it should output information about itself in a format that Munin understands. This includes how to label the chart, scaling information, how many series will be included on the chart, etc. When called with no arguments, the plugin should output the current values of each series. For more information on writing your own munin plugin, start with the HowToWritePlugins munin wiki page. And now, our plugin script:

#!/usr/bin/env ruby

# munin plugin to render rails response time graphs
# link to /etc/munin/plugins/avg_response_time and /etc/munin/plugins/max_response_time

require 'open-uri'
PORT = ENV['PORT'] || "8888"

def config
  title = File.basename($0).split('_').map{|s| s.capitalize }.join(' ')
  config=<<__END_CONFIG__
graph_title #{title}
graph_vlabel response time
graph_category rails
total.label total
rendering.label rendering
db.label db
__END_CONFIG__
  puts config
end

def get_data(read_only=false)
  qs = read_only ? '?debug' : ''
  puts open("http://127.0.0.1:#{PORT}/#{File.basename($0)}#{qs}").read
end

case ARGV.first
when 'config'
  config
when 'debug'
  get_data(true)
else
  get_data
end

The script will examine the name with which you linked it in to the munin plugins directory to determine which URI to query. I have also added a debug mode that will show you the current values, so you’re not consuming any data that munin needs to see for an accurate graph. The final piece is a small Daemons wrapper script to control the main log-tailing process, and you should be set. Make sure to restart munin-node so it will notice the new plugins, and after a while, you’ll see something like this:

It is worth noting that the numbers from the Rails log might not be 100% accurate, and this won’t replace the results that you can get from seriously profiling your application. Also, the information you are getting is a bit generic—all actions are lumped together, so there is not a lot of information about the cause of the performance problem. But, for insight into your production application performance, this setup should at least give you some indications about how well your baby is playing in the interwebs.

Download rails_log_monitor.rb

Download rails_response_time

So you’re building some righteous automation for your killer web 2.0 app, placing scripts in RAILS_ROOT/script that you can call from cron for nightly maintenance, etc. To bootstrap your rails environment, you decide to use the shebang feature of script/runner, available since changeset 5189. When you start to edit the script in TextMate (you are using TextMate, aren’t you?) there is no syntax highlighting to be found! It’s all plain text with no colors, and none of your ever-so-helpful keyboard macros work! Frightful. Well, take a deep breath, because together, we’re going to get the filetype detection magic working for you.

Before we get started, it’s helpful to know how filetype detection works. TextMate does a couple of different types of filetype detection—the first is based off of the extension, so if you named your script with a .rb extension, you are probably wondering what in the world I’m rambling about. Dude. It just works.

However, if you followed the rails convention for scripts, and did not use an extension with your filename, keep reading. The second type of detection works by scanning the so called “shebang” line at the top of the script which tells the shell (and in this case TextMate) which interpreter to use to evaluate your script—this is how we will tell TextMate that script/runner really means ruby.

First of all, you’ll need to fire up the Bundle Editor and select “Languages” from the drop-down filter. Expand the “Rails” node, and then select the “Ruby on Rails” language. On the right side, you should see the definition being used by TextMate to detect the Ruby on Rails scope. If you have not modified your bundle, you’ll probably see that it is using a fileTypes to look for .rxml files. This is where we want to insert the following line:

firstLineMatch = '^#!.*(script/runner)';

Here’s a screenshot of what it should look like when you are done:

Now go back to your script and enjoy all the colorized, scope-aware editing goodness that is TextMate!

I need some Mac users to test and give feed back on a very early version of the RailsLogAnalyzer. This app is an OSX app and not deployed on a server, so I would like to find out the obvious bug that may occur on different Macs. I tried it on my own MacBook Pro, G5 server, and on an old PowerBook G4. But then again the people most likely to use it are Rails developers that may have differences in their environment.

So if you like to take risks :-), understand the basic structure of a Rails app, have a production.log you want to analyze, and are not afraid of some scary bugs then read on…