Rails 3 app server startup time is long

Question

UPDATE 2 This is a known bug/feature with the way Ruby 1.9.2 loads files. http://twitter.com/#!/rails/status/72801149769621504

update: This started out as a question, but after working on this for a bit I think it might not be fixable. I figured I would post this in case anyone else is seeing the same thing and is wondering what is going on inside rails and bundler.

Is anyone else seeing long load times in their Rails 3 apps? I placed timers in environment.rb, application.rb, boot.rb and railties/lib/rails/initializable.rb. Time is measured in seconds and the elapsed time is the time since the last recorded time. Production load time takes a bit longer. Partly because of less hardware and also from eager_load! (and maybe from Thin vs Mongrel). Looks like Bundler is taking up a big chunk of the load time and I guess that is to be expected. I tested one of the apps in dev and prod, and one blank app in dev. I tested 2 app servers just to see if it was Thin causing it. I am also seeing similar things with Passenger in prod (which makes it unusable b/c of spawning behaviour in 2.2.15). I tested against edge Rails and the performance in dev was slightly worse 14.5s vs 14.2s. If I remove my testing dependencies it saves 2-3 seconds, but this does not help when I am running tests. I guess it is just a bit annoying waiting 5 minutes for all my Thin instances to restart and also waiting 15 seconds before my tests run, but it is an acceptable tradeoff at this point because of productivity I gain with Rails 3. If anyone has any ideas to help speed things up, I am all ears. Here are the test results:

Note: my app in Rails 2.3 loaded in less than 3 seconds in dev (although I have converted a little bit of the code to engines and added haml and twitter_oauth gems since the move to rails3)

**All tests conducted with Rails 3RC and Ruby 1.9.2rc2

Prod with Thin - CentOS 5.5, Rackspace cloud server 2GB instance
Test App #1 with 24 gem dependencies

start env.rb - Total=0
  start app.rb - 0.00110546 elapsed.  Total=0.001180052  
    start boot.rb - 0.000600488 elapsed.  Total=0.00178644    
    end boot.rb - 0.7935529 elapsed.  Total=0.795507318  
    start require rails/all - 0.000189127 elapsed.  Total=0.795701199  
    end require rails/all - 1.086998364 elapsed.  Total=1.882735263  
    start Bundler require - 0.000109708 elapsed.  Total=1.88285043  
    end Bundler require - 8.955853243 elapsed.  Total=10.838746673  
  end app.rb - 0.062975913 elapsed.  Total=10.901753753  
  # /railties-3.0.0.rc/lib/rails/initializable.rb 
  start run initializers - 0.000145906 elapsed.  Total=10.901910186  
    load_environment_config - 0.116689774 elapsed.  Total=11.018632298  
    initialize_cache - 0.246161343 elapsed.  Total=11.320543397  
    active_record.initialize_database - 0.080047485 elapsed.  Total=11.400961893  
    bootstrap_hook - 1.034189984 elapsed.  Total=12.451309104  
    active_support.initialize_time_zone - 1.969821814 elapsed.  Total=14.448777651  
    action_controller.set_configs - 0.594991537 elapsed.  Total=15.044692126  
    will_paginate.active_record - 0.324460921 elapsed.  Total=15.386837641  
    will_paginate.action_view - 1.904889132 elapsed.  Total=17.328981523  
    add_view_paths - 0.087811847 elapsed.  Total=17.42011881  
    load_init_rb - 0.151282681 elapsed.  Total=17.709093173  
    load_init_rb - 0.362241273 elapsed.  Total=18.071865548  
    load_config_initializers - 0.144051305 elapsed.  Total=18.217433492  
    build_middleware_stack - 2.569453884 elapsed.  Total=20.826842081  
    eager_load! - 4.165919064 elapsed.  Total=24.99280168  
    finisher_hook - 0.48795935 elapsed.  Total=25.480807439  
    repopulate_roles - 0.504085662 elapsed.  Total=25.984901297  
  end run initializers - ~0.00005 elapsed.  Total=25.985617783  
end env.rb - ~0.00006 elapsed.  Total=25.985683903  

Dev with Mongrel - Max OSX 10.5.8, 2.66 Core2duo, 4GB RAM
Test App #1 with 24 gem dependencies

start boot.rb (Bundler.setup) - 2.0e-05 elapsed.  Total=3.1e-05  
end boot.rb (Bundler.setup) - 2.352435 elapsed.  Total=2.352915  
start app.rb - 0.084945 elapsed.  Total=2.437866  
  start require rails/all - 0.000181 elapsed.  Total=2.438049  
  end require rails/all - 0.489425 elapsed.  Total=2.927485  
  start Bundler.require(:default, Rails.env) - 5.6e-05 elapsed.  Total=2.927544  
  end Bundler.require(:default, Rails.env) - 5.16162 elapsed.  Total=8.089177  
end app.rb - 0.025972 elapsed.  Total=8.11516  
start env.rb - 0.084153 elapsed.  Total=8.199329 
  # /railties-3.0.0.rc/lib/rails/initializable.rb 
  start run_initializers - 0.002709 elapsed.  Total=8.202042   
    initialize_cache - 0.089231 elapsed.  Total=8.518005  
    bootstrap_hook - 0.602342 elapsed.  Total=9.192564  
    active_support.initialize_time_zone - 0.901676 elapsed.  Total=10.10115  
    action_controller.set_configs - 0.375864 elapsed.  Total=10.477565  
    will_paginate.active_record - 0.207447 elapsed.  Total=10.694479  
    will_paginate.action_view - 1.041412 elapsed.  Total=11.75974  
    load_init_rb - 0.051938 elapsed.  Total=11.879547  
    load_init_rb - 0.082936 elapsed.  Total=12.001311  
    load_init_rb - 0.18798 elapsed.  Total=12.189555  
    load_config_initializers - 0.079461 elapsed.  Total=12.269971  
    build_middleware_stack - 1.390042 elapsed.  Total=13.729273  
    finisher_hook - 0.082274 elapsed.  Total=13.811648  
    repopulate_roles - 0.350287 elapsed.  Total=14.161941  
  end run_initializers - 3.0e-06 elapsed.  Total=14.177869  
end env.rb - 0.000127 elapsed.  Total=14.178002  

Dev with Mongrel Test App #2 with 2 gem dependencies

start boot.rb (Bundler.setup) - Total=0
end boot.rb (Bundler.setup) - 1.724158 elapsed.  Total=1.724199
start app.rb - 0.041006 elapsed.  Total=1.765211
  start require rails - 0.000151 elapsed.  Total=1.765364
  end require rails - 0.360051 elapsed.  Total=2.125426
  start Bundler.require(:default, Rails.env) - 5.5e-05 elapsed.  Total=2.125485
  end Bundler.require(:default, Rails.env) - 0.008396 elapsed.  Total=2.133889
end app.rb - 0.007805 elapsed.  Total=2.141704
start env.rb - 0.16541 elapsed.  Total=2.307128
  start run_initializers - 0.00031 elapsed.  Total=2.307442
    load_active_support - 0.24045 elapsed.  Total=2.579421
    active_support.initialize_time_zone - 0.206237 elapsed.  Total=2.837663
    action_controller.deprecated_routes - 0.210291 elapsed.  Total=3.048634
    build_middleware_stack - 0.220663 elapsed.  Total=3.273035
  end run_initializers - 3.0e-06 elapsed.  Total=3.29339
end env.rb - 8.7e-05 elapsed.  Total=3.293483

Answer 1

Since this is a fairly old question: Have you tested it with the release version of Rails 3?

That is a long time but ultimately meaningless. My rails apps stay up for months at a time so that is a fraction of a fraction of 1 percent of the total runtime.

Do you have a ton of dependencies that Bundler has to deal with? I can get my Rails 3 app started in less than 2 seconds in any environment, but I use very few third party gems.

Answer 2

Bundler often spends more than half of its time requiring gems. Are any of the dependencies that you are loading unnecessary in dev/test mode? For instance, some of my gems are only used by resque workers or in other scripts. You can add :require => false and then manually require them when you need them for some modest startup speed gains in dev/test mode.

Before doing so, I usually profile the require statements (in lib/bundler/runtime.rb) to see if they're actually worth taking out.