Why does Ruby on Rails take so long to start?

Question

I'm running Ruby on Rails on a 2011 Macbook Pro with 8GB of RAM. I takes 2 seconds to start rails with no options, and it takes 12 seconds to load the console. What is Rails doing in this time? I can't believe that it is taking 12 seconds. My app is not that big – 10,607 lines in the app folder.

$ time rails > /dev/null

real    0m2.830s
user    0m2.751s
sys 0m0.076s

$ time echo exit | rails console > /dev/null

real    0m12.825s
user    0m11.779s
sys 0m0.898s

I'm running Ruby 1.9.3 and Rails 3.2:

$ ruby -v
ruby 1.9.3p327 (2012-11-10 revision 37606) [x86_64-darwin12.0.0]
$ rails -v
Rails 3.2.11
$ wc -l `find app -name *.rb`
10607 total

Edit:

Doing the same with an empty rails project (just rails new):

marc@menasor ~/dev/rails_empty $ time rails > /dev/null
real    0m2.192s
marc@menasor ~/dev/rails_empty $ time echo exit | rails c > /dev/null
real    0m3.807s

So that's nearly 4 seconds to start an empty rails project. What is happening for those 4 seconds?

Here is some timings for starting my original Rails project on a Macbook Air with an SSD with 4GB RAM.

$ time rails
real    0m1.161s
$ time echo exit | rails console
real    0m20.356s

So the SDD reduced rails startup time be nearly 2 seconds, so I assume that is doing a lot of IO. The time to start the rails console has gone up though.

Edit:

Adding profiling data after Reck's suggestion:

Total: 404 samples
 116  28.7%  28.7%      116  28.7% garbage_collector
  62  15.3%  44.1%      258  63.9% Kernel#require
  12   3.0%  47.0%       28   6.9% Journey::Visitors::Each#visit
  12   3.0%  50.0%       12   3.0% Regexp#===
   9   2.2%  52.2%       52  12.9% Module#class_eval
   9   2.2%  54.5%       12   3.0% Module#module_eval
   9   2.2%  56.7%        9   2.2% Module#remove_method
   8   2.0%  58.7%        9   2.2% Module#enable
   7   1.7%  60.4%       24   5.9% Journey::Visitors::Visitor#visit
   6   1.5%  61.9%      255  63.1% Kernel#tap
   5   1.2%  63.1%      237  58.7% BasicObject#instance_exec
   5   1.2%  64.4%        5   1.2% Psych::Nodes::Scalar#initialize
   4   1.0%  65.3%        8   2.0% Array#uniq
   4   1.0%  66.3%       11   2.7% Enumerable#inject
   4   1.0%  67.3%       71  17.6% Kernel#load
   4   1.0%  68.3%       61  15.1% Kernel.load

Answer 1

We could just profile the rails boot sequence and see if we learn anything from that.

• add gem 'perftools.rb' to your gemfile (the '.rb' bit is not a typo)
• run bundle install
• add require 'perftools' to the top of /environments/development.rb
• add PerfTools::CpuProfiler.start('/tmp/dev_prof') to the configure block in development.rb
• choose an url that you can easily visit within your app. In my case the url is localhost:3000/games.
• find the controller method that handles that url call. In my case, it's the index method in the GamesController.
• add require 'perftools' to the top of the GamesController
• add PerfTools::CpuProfiler.stop to the index method of the GamesController.

Now start the rails development environment with 'rails s'.

• once rails is loaded go and visit localhost:3000/games, which causes the profiler to write to /tmp/dev_prof.
• navigate to the /tmp folder and run 'pprof.rb --tex /tmp/dev_prof | less'

The calls at the top are the ones taking up the most time. You will probably notice that quite a bit of time gets taken up by the garbage collector. Luckily we can improve this:

• run 'export RUBY_GC_MALLOC_LIMIT=60000000'
• run 'export RUBY_FREE_MIN=200000'

When you redo your profiling, the garbage collector should be taking up much less time now. See http://whalesalad.com/posts/reduce-rails-boot-time-by-30-40-percent for additional information.

Before:
  82  35.8%  35.8%       82  35.8% garbage_collector
  30  13.1%  48.9%      131  57.2% Kernel#require
   9   3.9%  52.8%        9   3.9% Regexp#===
   6   2.6%  55.5%       25  10.9% Module#class_eval
   5   2.2%  57.6%        8   3.5% Module#module_eval
   4   1.7%  59.4%        9   3.9% Journey::Visitors::Visitor#visit
   4   1.7%  61.1%      129  56.3% Kernel#tap
   4   1.7%  62.9%       33  14.4% Kernel.load
   4   1.7%  64.6%        4   1.7% Module#enable
   3   1.3%  65.9%        3   1.3% Enumerable#any?
   3   1.3%  67.2%       20   8.7% EventMachine.run_machine

After:
  33  18.1%  18.1%       33  18.1% garbage_collector
  31  17.0%  35.2%      137  75.3% Kernel#require
   5   2.7%  37.9%        6   3.3% Module#enable
   5   2.7%  40.7%        6   3.3% Module#module_eval
   5   2.7%  43.4%        5   2.7% Regexp#===
   4   2.2%  45.6%      125  68.7% BasicObject#instance_exec
   4   2.2%  47.8%       20  11.0% EventMachine.run_machine

Answer 2

I was having the same issues, though my laptop is 4 years old and only 4gb RAM, however I am now using this: https://github.com/thedarkone/rails-dev-boost

for me it has cut the time down to seconds ( 3/4) to load the environment. Hopefully it may help you