Performance Regression in Rails 3.1 boot time #734

Closed
robolson opened this Issue May 16, 2011 · 16 comments

Comments

Projects
None yet
9 participants
@robolson
Contributor

robolson commented May 16, 2011

I created two barebones Rails projects. One with Rails 3.0.7 and the other with 3.1.0.beta1. Both are using Ruby 1.9.2p180 and SQLite for the db. Running this very basic script with Rails runner, Rails 3.1 takes twice as long to load in 3.1 versus 3.0.

# the test
echo puts Time.now > test_script
time rails runner test_script

# Rails 3.0.7
time rails runner test_script

real    0m2.125s
user    0m1.668s
sys     0m0.443s

# Rails 3.1.0.beta.1
time rails runner test_script

real    0m4.601s
user    0m3.800s
sys     0m0.781s
@josevalim

This comment has been minimized.

Show comment
Hide comment
@josevalim

josevalim May 16, 2011

Contributor

@robolson we really appreciate that you benchmark Rails! Could you please try to identify exactly what got slower? Maybe it is because Rails now has more dependencies? If you can pinpoint the problem, it will be much easier for us to solve it.

Contributor

josevalim commented May 16, 2011

@robolson we really appreciate that you benchmark Rails! Could you please try to identify exactly what got slower? Maybe it is because Rails now has more dependencies? If you can pinpoint the problem, it will be much easier for us to solve it.

@spastorino

This comment has been minimized.

Show comment
Hide comment
@spastorino

spastorino Jul 12, 2011

Member

Could this be related to the require issue in Ruby 1.9.2?.
@robolson can you give us more details?

Member

spastorino commented Jul 12, 2011

Could this be related to the require issue in Ruby 1.9.2?.
@robolson can you give us more details?

@robolson

This comment has been minimized.

Show comment
Hide comment
@robolson

robolson Jul 12, 2011

Contributor

@spastorino It could not be related to the require issue in Ruby 1.9.2 because both benchmarks were run under 1.9.2 so they were equally affected. Something actually changed in Rails to make it take longer, possibly more dependencies like Jose hypothesized.

@josevalim sorry for never responding. I'm afraid I do not have the ruby-prof chops to narrow this down. However, I wanted to make the core team aware of the significant regression.

Contributor

robolson commented Jul 12, 2011

@spastorino It could not be related to the require issue in Ruby 1.9.2 because both benchmarks were run under 1.9.2 so they were equally affected. Something actually changed in Rails to make it take longer, possibly more dependencies like Jose hypothesized.

@josevalim sorry for never responding. I'm afraid I do not have the ruby-prof chops to narrow this down. However, I wanted to make the core team aware of the significant regression.

@gnufied

This comment has been minimized.

Show comment
Hide comment
@gnufied

gnufied Jul 23, 2011

Contributor

Okay trying this out with

Rails 3.1.0-rc4:

rails_bugmash/issue_734> time rails runner test_script
rails runner test_script  1.29s user 0.22s system 99% cpu 1.519 total

With Rails 3.0.9:

rails_bugmash/another> time rails runner test_script                                                                                                   
rails runner test_script  1.26s user 0.23s system 99% cpu 1.491 total

I can look into profiling this, provided a consistent test-case, but I am not seeing such a big difference here. I am using Ruby-1.9.2-p290 and rails with sqlite3.

Contributor

gnufied commented Jul 23, 2011

Okay trying this out with

Rails 3.1.0-rc4:

rails_bugmash/issue_734> time rails runner test_script
rails runner test_script  1.29s user 0.22s system 99% cpu 1.519 total

With Rails 3.0.9:

rails_bugmash/another> time rails runner test_script                                                                                                   
rails runner test_script  1.26s user 0.23s system 99% cpu 1.491 total

I can look into profiling this, provided a consistent test-case, but I am not seeing such a big difference here. I am using Ruby-1.9.2-p290 and rails with sqlite3.

@spastorino

This comment has been minimized.

Show comment
Hide comment
@spastorino

spastorino Jul 23, 2011

Member

I'm getting this

➜  myapp307  time bundle exec rails runner ../test_script
bundle exec rails runner ../test_script  1.81s user 0.39s system 77% cpu 2.836 total
➜  myapp309  time bundle exec rails runner ../test_script
bundle exec rails runner ../test_script  1.89s user 0.39s system 99% cpu 2.277 total
➜  myapp310  time bundle exec rails runner ../test_script
bundle exec rails runner ../test_script  4.01s user 0.74s system 65% cpu 7.249 total

@gnufied are you testing with 3-1-stable latest code?

Member

spastorino commented Jul 23, 2011

I'm getting this

➜  myapp307  time bundle exec rails runner ../test_script
bundle exec rails runner ../test_script  1.81s user 0.39s system 77% cpu 2.836 total
➜  myapp309  time bundle exec rails runner ../test_script
bundle exec rails runner ../test_script  1.89s user 0.39s system 99% cpu 2.277 total
➜  myapp310  time bundle exec rails runner ../test_script
bundle exec rails runner ../test_script  4.01s user 0.74s system 65% cpu 7.249 total

@gnufied are you testing with 3-1-stable latest code?

@robolson

This comment has been minimized.

Show comment
Hide comment
@robolson

robolson Jul 23, 2011

Contributor

@gnufied: Wow you must have a very fast computer.

A tried the experiment again. This time with 1.9.2-p290 and Rails 3.1.0-rc4. The issue only seems to have gotten worse.

# Rails 3.1.0.rc4
time rails runner test_script

real    0m5.125s
user    0m4.330s
sys     0m0.803s
Contributor

robolson commented Jul 23, 2011

@gnufied: Wow you must have a very fast computer.

A tried the experiment again. This time with 1.9.2-p290 and Rails 3.1.0-rc4. The issue only seems to have gotten worse.

# Rails 3.1.0.rc4
time rails runner test_script

real    0m5.125s
user    0m4.330s
sys     0m0.803s
@gnufied

This comment has been minimized.

Show comment
Hide comment
@gnufied

gnufied Jul 23, 2011

Contributor

@robolson, https://gist.github.com/1101699

@spastorino , no still with 3.1.0-rc4, but will it make that big difference?

Anyways, please run it couple of times to arrive on a conclusion.

Contributor

gnufied commented Jul 23, 2011

@robolson, https://gist.github.com/1101699

@spastorino , no still with 3.1.0-rc4, but will it make that big difference?

Anyways, please run it couple of times to arrive on a conclusion.

@spastorino

This comment has been minimized.

Show comment
Hide comment
@spastorino

spastorino Jul 23, 2011

Member

@gnufied I've just pasted the output as if I had run it once but actually I did it a couple of times and got exactly the same thing.

Member

spastorino commented Jul 23, 2011

@gnufied I've just pasted the output as if I had run it once but actually I did it a couple of times and got exactly the same thing.

@bmarini

This comment has been minimized.

Show comment
Hide comment
@bmarini

bmarini Jul 25, 2011

Contributor

Hey guys I threw up a project to help debug this, making use of the profile tool included in the rails repo.
https://github.com/bmarini/profile-rails-startup

I got the following results, profiling a require of config/environment.rb (full result here)

3-0:   27413.36 KB 120600 obj  667.1 ms 19732 KB RSS 115.9 ms GC time 4 GC runs
3-1:   63571.32 KB 262752 obj 1919.5 ms 26568 KB RSS 436.2 ms GC time 5 GC runs

It looks as though 3-1 loads a little more than double the number of objects into memory and triggers an extra GC run on my machine.

Contributor

bmarini commented Jul 25, 2011

Hey guys I threw up a project to help debug this, making use of the profile tool included in the rails repo.
https://github.com/bmarini/profile-rails-startup

I got the following results, profiling a require of config/environment.rb (full result here)

3-0:   27413.36 KB 120600 obj  667.1 ms 19732 KB RSS 115.9 ms GC time 4 GC runs
3-1:   63571.32 KB 262752 obj 1919.5 ms 26568 KB RSS 436.2 ms GC time 5 GC runs

It looks as though 3-1 loads a little more than double the number of objects into memory and triggers an extra GC run on my machine.

@radar

This comment has been minimized.

Show comment
Hide comment
@radar

radar Jul 26, 2011

Contributor

Is this perhaps to do with the extra dependencies like coffee-script and not Rails itself? Just a thought.

Contributor

radar commented Jul 26, 2011

Is this perhaps to do with the extra dependencies like coffee-script and not Rails itself? Just a thought.

@stefanpenner

This comment has been minimized.

Show comment
Hide comment
@stefanpenner

stefanpenner Jul 26, 2011

Contributor

Related: this problem seems to be exponential, on our larger apps, we are seeing 20+ second boot times.

The problem seems to be affected by a slow 1.9.2 require, with a large load path, 88 gems ( including nested dependencies), as well as extra object allocations in 3.1.

Over the weekend I wanted to see exactly how much time (in a real world app) the whole massive load path was costing us.

Details

  • ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.0.0]
  • rails 3.1 rc4 + 88 Gems
  • 2.8ghz Core 2 duo + SSD + 6gb of ram( OSX Lion)

So I:

  • compact the load path, by taking all gems, putting them in the same master directory.
  • Patched the app not to allow bundler to play with the load path
  • use bundler to provide the correct require order
  • required all gems directly from the new master gem directory

Issues:

  • compatibility
  • some gems needed to be patched (only 5 or so, our of 88)
  • some rails engines (and im assuming other gems) actually look into the load path to do stuff (and dont work without patching)
  • feels dirty

Outcome

  • 8s app boot time, instead of 20 seconds ( 250% speed up)

Now 8s is a huge improvement over 20, but I would like to see this hopefully be the baseline sometime soon, open for more optimizations.

Conclusion
I'm sure the extra object allocations aren't helping, but we can drastically improve rails boot time, by working specifically on ruby's require and load_path issues.

Hopefully I will be able to squeeze out some time to continue working on this.

Contributor

stefanpenner commented Jul 26, 2011

Related: this problem seems to be exponential, on our larger apps, we are seeing 20+ second boot times.

The problem seems to be affected by a slow 1.9.2 require, with a large load path, 88 gems ( including nested dependencies), as well as extra object allocations in 3.1.

Over the weekend I wanted to see exactly how much time (in a real world app) the whole massive load path was costing us.

Details

  • ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.0.0]
  • rails 3.1 rc4 + 88 Gems
  • 2.8ghz Core 2 duo + SSD + 6gb of ram( OSX Lion)

So I:

  • compact the load path, by taking all gems, putting them in the same master directory.
  • Patched the app not to allow bundler to play with the load path
  • use bundler to provide the correct require order
  • required all gems directly from the new master gem directory

Issues:

  • compatibility
  • some gems needed to be patched (only 5 or so, our of 88)
  • some rails engines (and im assuming other gems) actually look into the load path to do stuff (and dont work without patching)
  • feels dirty

Outcome

  • 8s app boot time, instead of 20 seconds ( 250% speed up)

Now 8s is a huge improvement over 20, but I would like to see this hopefully be the baseline sometime soon, open for more optimizations.

Conclusion
I'm sure the extra object allocations aren't helping, but we can drastically improve rails boot time, by working specifically on ruby's require and load_path issues.

Hopefully I will be able to squeeze out some time to continue working on this.

@dhh

This comment has been minimized.

Show comment
Hide comment
@dhh

dhh Jul 31, 2011

Member

Can someone test this on 1.9.3? Supposedly the slow require issue is much improved there.

Member

dhh commented Jul 31, 2011

Can someone test this on 1.9.3? Supposedly the slow require issue is much improved there.

@spastorino

This comment has been minimized.

Show comment
Hide comment
@spastorino

spastorino Jul 31, 2011

Member

With 1.9.3

➜  myapp  time bundle exec rails runner test_script
bundle exec rails runner test_script  2.37s user 0.38s system 99% cpu 2.773 total
➜  myapp_test  time bundle exec rails runner test_script
bundle exec rails runner test_script  2.38s user 0.36s system 99% cpu 2.765 total
➜  myapp_test  time bundle exec rails runner test_script
bundle exec rails runner test_script  2.40s user 0.37s system 99% cpu 2.785 total

I'm still thinking this could be related to the require issue, since 3.1 has much more deps now we can't compare to 3.0 directly.

Member

spastorino commented Jul 31, 2011

With 1.9.3

➜  myapp  time bundle exec rails runner test_script
bundle exec rails runner test_script  2.37s user 0.38s system 99% cpu 2.773 total
➜  myapp_test  time bundle exec rails runner test_script
bundle exec rails runner test_script  2.38s user 0.36s system 99% cpu 2.765 total
➜  myapp_test  time bundle exec rails runner test_script
bundle exec rails runner test_script  2.40s user 0.37s system 99% cpu 2.785 total

I'm still thinking this could be related to the require issue, since 3.1 has much more deps now we can't compare to 3.0 directly.

@spastorino

This comment has been minimized.

Show comment
Hide comment
@spastorino

spastorino Jul 31, 2011

Member

With 1.9.3 and the same Gemfile 3.0 has

➜  myapp  time bundle exec rails runner test_script
bundle exec rails runner test_script  1.95s user 0.21s system 99% cpu 2.165 total

This is practically the same time I was getting in 3.0.9

Member

spastorino commented Jul 31, 2011

With 1.9.3 and the same Gemfile 3.0 has

➜  myapp  time bundle exec rails runner test_script
bundle exec rails runner test_script  1.95s user 0.21s system 99% cpu 2.165 total

This is practically the same time I was getting in 3.0.9

@jonleighton

This comment has been minimized.

Show comment
Hide comment
@jonleighton

jonleighton Aug 15, 2011

Member

I have made a bit of an improvement in development mode by making sass-rails less eager about requiring stuff: rails/sass-rails@c2f9d66

Member

jonleighton commented Aug 15, 2011

I have made a bit of an improvement in development mode by making sass-rails less eager about requiring stuff: rails/sass-rails@c2f9d66

jonleighton added a commit that referenced this issue Aug 16, 2011

Don't refer to ActionController::Base in the wrap_parameters initiali…
…zer - use config object instead. Cuts about 15% off the load time. (#734)

jonleighton added a commit that referenced this issue Aug 16, 2011

Don't refer to ActionController::Base in the wrap_parameters initiali…
…zer - use config object instead. Cuts about 15% off the load time. (#734)
@jonleighton

This comment has been minimized.

Show comment
Hide comment
@jonleighton

jonleighton Aug 16, 2011

Member

I am closing this because startup time is roughly halved by recent changes. It's still a bit slower than 3.0, and there are still some optimisations that could be made, but that stuff won't be done for the 3.1.0 release.

Member

jonleighton commented Aug 16, 2011

I am closing this because startup time is roughly halved by recent changes. It's still a bit slower than 3.0, and there are still some optimisations that could be made, but that stuff won't be done for the 3.1.0 release.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment