Rapid Rails: Boot Up Time

Rails boot up time really starts to drag when you’re working in a TDD or BDD style. There’s projects out there that create long running distributed processes to ease this, but it’s interesting to look at exactly why Rails might boot up slowly.

I have a project that isn’t massively complicated, but it has suffered from “just add” culture. I’ve been told to “just add” Excel support, PDF generation, and a lot more features that require complex libraries. This naturally increases the memory footprint of my application, and it also increases boot time.

Before I started my analysis, the boot time averaged at 11.6 seconds. After my improvements the boot time is 7 seconds. By comparison, the code for Deadline boots in 4 seconds, but it has few dependencies (it’s a joy to work on by the way).

Before continuing this technical and possibly dull article, I’ve mined my internet meme library to add a soundtrack. Replace all instances of on a boat with on Rails:

And I don’t think we even get SNL in the UK!

Analysing boot up time

Boot up time shouldn’t be related to the number of models and controllers you have. Rails dependency loading should require these files when they’re first referenced — unless you use a plugin like ThinkingSphinx that intentionally loads models on start up.

To prove this, add this to the first line of a model file: puts "I've been required", then start script/console. Unless something is including the model, you shouldn't see the message until you type the model's class name and press return.

So what’s increasing my app’s carbon footprint if it’s not my own code? To find out, I wrapped up each major block of code in environment.rb in Benchmark.measure blocks. I found that my library requires were using most of the time. Also, this code took over a second:

ActiveSupport::Inflector.inflections do |inflect|
  inflect.irregular 'cookie', 'cookies'
end

I have that code because even though Rails correctly pluralises it gets the relationship wrong in a has_many (it looks for LoginCooky). But why would that take a second? I have no idea. Seeing as I technically shouldn't need this definition I ignored it for now.

Requires

The gem requires in environment.rb were the real culprit. If you think about what Ruby does here it's obvious: the amount of code evaluated for some libraries will be huge.

This project is old and wasn’t using config.gem, so I added calls to that in the Rails::Initializer.run block instead of plain old require. This is cool because Rails will prompt missing library installation, but it's also cool because of this:

config.gem 'scruffy', :lib => false

Setting the lib to false will make Rails aware you want the library, but not require it. This library is only used in one place, there’s a GraphController that manages dynamic graph generation. I added a require 'scruffy' to that file instead.

This doesn’t always make sense of course: there might be calls all over your code to a particular library. That’s fine, just require it at boot. The amount of times that wasn’t the case, however, reduced my boot time by 4 seconds.

Forensics

I’m not exactly Grissom or Horatio, but I did write a little script to watch the require time of every require in the project. I required it in environment.rb and watched to see which libraries seemed slow. I've left my commented out bits where I was trying to figure out how to only measure "top level" requires in environment.rb -- I never fully figured this out, does anyone know how to do it?

require 'benchmark'
 
module Kernel
  alias old_require require
 
  def require(path)
    #unless caller.find { |caller_line| caller_line.match /dependencies\.rb/ }
    #  return old_require(path)
    #end
 
    output = nil
    @required_files ||= []
 
    benchmark = Benchmark.measure do
      output = old_require path
    end
 
    @required_files << [path, benchmark]
 
    puts path
    caller.each do |caller_line|
      puts "\t#{caller_line}"
    end
    puts ""
 
    #puts "#{path}:"
    #puts loading_benchmark
 
    output
  end
 
  def print_require_benchmark_stats
    puts "Printing benchmark stats:"
    @required_files ||= []
    @required_files.sort! { |a, b| b[1].real <=> a[1].real }
    @required_files.each do |path, benchmark|
      puts path
      puts benchmark
    end
  end
end
 
at_exit { print_require_benchmark_stats }

Lessons

It’s interesting what you learn by looking at older Rails projects. I always used to just require my libraries in the environment file so other developers would see the app break if they hadn’t installed them. The newer way, config.gem, provides a better solution and lets us require files when we actually need them.