Extremely slow start up with ruby 1.9.1 vs 1.8.7

rubyonrails-talk
1

I created a fresh new rails app, no gems, no nothing. Completely unmodified. Doing anything that initializes rails takes 2 - 3 times longer in ruby 1.9.1 than it does in 1.8.7. Obviously with a fresh rails app, this is only 2 - 3 seconds extra. But with a decent sized app, this can take up to 25 seconds for rails to initialize, vs the 12 seconds in 1.8.7.

I've been racking my brain on this all day. I don't know where to begin. Any ideas what might be causing the problem or a way to profile the code and figure out what is taking so long?

The reason its an issue for me, heroku times out before my app has a chance to start, displaying an error message that the app times out.

Any help is appreciated. Thanks.

2

Ben, did you ever figure out anything here? I'm experiencing the same problem with 1.9.2: https://gist.github.com/756616

3

I am seeing a similar issue with startup between Rails 3 with 1.9.2 and Rails 2 with 1.8.7, though I have not investigated whether it is ruby or rails that is the issue. For example if I do rake db:migrate with nothing to do it takes 7 seconds on the former but only 2 on the latter. I see the same effect starting tests and so on. It is a bit of a pain. I am using rvm and bundler in both cases.

Colin

4

I have done some further tests and confirmed that it is Ruby 1.9.2 that is causing the problem. I am comparing a Rails 3 app with ruby 1.9.2p0 (2010-08-18 revision 29036) [i686-linux] against ruby 1.8.7 (2010-08-16 patchlevel 302) [i686-linux]. With a small app, as mentioned above, an empty rake db:migrate takes 7 seconds rather than 2 and Rake test takes 40 seconds on 1.9.2 versus 11 on 1.8.7. This is on Ubuntu 10.04.

Any suggestions anyone?

Colin

5

I have now tried this with ruby 1.9.2 p136 and it has not helped. When I look at the processor utilisation I see that rake is consuming all my available processor for most of the time. Can anyone confirm that they are using 1.9.2 with rails 3 (preferably on Ubuntu or similar) without seeing the slowdown that I have experienced. Alternatively can anyone suggest where I go from here (apart from buying a more powerful PC).

Colin

6

Can I just check that you are confirming that you see a significant slow down between Ruby 1.8.7 and 1.9.2?

Colin

7

Ben, did you ever figure out anything here? I’m experiencing the same

problem with 1.9.2: https://gist.github.com/756616

I am seeing a similar issue with startup between Rails 3 with 1.9.2

and Rails 2 with 1.8.7, though I have not investigated whether it is

ruby or rails that is the issue. For example if I do rake db:migrate

with nothing to do it takes 7 seconds on the former but only 2 on the

latter. I see the same effect starting tests and so on. It is a bit

of a pain. I am using rvm and bundler in both cases.

I have done some further tests and confirmed that it is Ruby 1.9.2

that is causing the problem. I am comparing a Rails 3 app with ruby

1.9.2p0 (2010-08-18 revision 29036) [i686-linux] against ruby 1.8.7

(2010-08-16 patchlevel 302) [i686-linux]. With a small app, as

mentioned above, an empty rake db:migrate takes 7 seconds rather than

2 and Rake test takes 40 seconds on 1.9.2 versus 11 on 1.8.7. This is

on Ubuntu 10.04.

I have now tried this with ruby 1.9.2 p136 and it has not helped.

When I look at the processor utilisation I see that rake is consuming

all my available processor for most of the time. Can anyone confirm

that they are using 1.9.2 with rails 3 (preferably on Ubuntu or

similar) without seeing the slowdown that I have experienced.

Alternatively can anyone suggest where I go from here (apart from

buying a more powerful PC).

Colin

Colin, do you have a sample application? Next, it really depends

on your overall system and Rails app configuration. For example,

if you don’t have enough RAM, your system move data from memory

to the disk and vice-versa. This is a huge performance hit. Can you

provide more information?

-Conrad

8

I have 1GByte RAM and while running the test it shows less than half used and the disk is not rattling. The processor shows 100% utilisation whilst the test is running, with rake being the process using most of it.

I have tried making a new rails 3.0.3 app rails new testruby then using rvm to switch between 1.8.7 p302 and 1.9.2 p136

On each ruby I ran time rake db:migrate a couple of times to let the disk cache settle out then for 1.8.7 I got real 0m2.111s user 0m1.804s sys 0m0.220s

and on 1.9.2 real 0m4.098s user 0m3.512s sys 0m0.424s

I also tried rake test and got, on 1.8.7 real 0m3.615s user 0m3.104s sys 0m0.316s

and on 1.9.2 real 0m6.487s user 0m5.320s sys 0m0.684s

It seems as if 1.9.2 takes about twice as long for some reason.

Colin

9

On a bare app I get the same numbers as you show in your gist (about a 2x factor for sys and real times).

On my relatively new app's specs I get these:

Using ~/.rvm/gems/ruby-1.9.2-p136 with gemset rails3

% time rake spec real 1m3.337s user 0m41.383s sys 0m3.760s

Using ~/.rvm/gems/ruby-1.8.7-p330 with gemset rails3

% time rake spec real 0m21.948s user 0m12.721s sys 0m2.248s

I ran each rvm 5 times and they're very consistent. The CPU is at 45%, I have 2G ram and the app footprint in test is much smaller than that (~500M).

Interesting that the ratios between the sys times and the real times are not tracking relative to the bare app. The real time going to 3x is nasty.

I think I'll do a ruby-prof next.

-cpr

10

… Colin, do you have a sample application? Next, it really depends

on your overall system and Rails app configuration. For example,

if you don’t have enough RAM, your system move data from memory

to the disk and vice-versa. This is a huge performance hit. Can you

provide more information?

I have 1GByte RAM and while running the test it shows less than half

used and the disk is not rattling. The processor shows 100%

utilisation whilst the test is running, with rake being the process

using most of it.

I have tried making a new rails 3.0.3 app

rails new testruby

then using rvm to switch between 1.8.7 p302 and 1.9.2 p136

On each ruby I ran

time rake db:migrate

a couple of times to let the disk cache settle out then for 1.8.7 I got

real 0m2.111s

user 0m1.804s

sys 0m0.220s

and on 1.9.2

real 0m4.098s

user 0m3.512s

sys 0m0.424s

I also tried rake test and got, on 1.8.7

real 0m3.615s

user 0m3.104s

sys 0m0.316s

and on 1.9.2

real 0m6.487s

user 0m5.320s

sys 0m0.684s

It seems as if 1.9.2 takes about twice as long for some reason.

Colin

Colin, do you have a test case that I can run locally? Or can you

tell me the specifics? Next, I’m not sure that 1 GB RAM is sufficient

because other resources outside the actual application uses the RAM.

For example, on my slower machine, iMac, with 4 GB Ram, the RAM

utilization for some common applications are as follows:

Safari 5 ~554.0 MB

Textmate ~96.1 MB

Terminal ~14.0 MB

Chrome ~199.6 MB

Firefox ~128.2 MB

and so on

Note: The above doesn’t include any of the OS specific processes but

you can see that this adds up. Also, most modern OS will reserve RAM

for its use that cannot be used by the end user. Just something to keep

in mind.

Lastly, in regards to running spec, I tend to use Ruby Spork gem because

anytime you do ‘rake spec’, the Rails framework needs to be loaded before

the application specific code can be executed. This is also true when running

‘rake db:migrate’

Good luck,

-Conrad

11

Hi Colin and all,

I had exactly the same here: 1GB RAM, Ubuntu, RVM with Ruby1.9 and Rails - and it's terribly slow comparing with the elder Ruby and Rails combo. Did you figured out anything?

Also how did you speed up your server running? I already use Thin locally, and found it"s faster then Webrick, but still have to wait a lot after loading. Any trick?

Thanks, Zoli

12

Hi Colin and all,

I had exactly the same here: 1GB RAM, Ubuntu, RVM with Ruby1.9 and Rails - and it's terribly slow comparing with the elder Ruby and Rails combo. Did you figured out anything?

Also how did you speed up your server running? I already use Thin locally, and found it"s faster then Webrick, but still have to wait a lot after loading. Any trick?

I use mongrel. The server startup time is not really an issue for me in development as starting the server is not something that happens repeatedly. I don't know whether the response time once the server is up and running is significantly different between 1.9.2 and 1.8.7, I had not noticed an obvious difference. It is the test cycle time particularly that is a pain. I use autotest and when I make a change I have to wait while the tests get underway, which is tedious.

Colin

13

Using ruby-prof I captured the CPU time of the startup of my 3.0.3 Rails app (https://gist.github.com/762764):

ruby-1.8.7-p330 (Total CPU: 8.573606)

%self total self wait child calls name 20.99 8.50 1.80 0.00 8.49 1898 Kernel#require 10.16 0.87 0.87 0.00 0.00 17128 Module#constants   6.71 0.82 0.58 0.00 0.25 3691 Array#select   6.22 8.00 0.53 0.00 7.95 58841 Array#each   4.16 1.85 0.36 0.00 1.66 14214 Array#map

ruby-1.9.2-p136 (Total CPU 16.794391)

%self total self wait child calls name 39.93 16.47 6.71 0.00 16.46 1904 Kernel#require   3.85 2.51 0.65 0.00 2.23 14252 Array#map   3.61 0.61 0.61 0.00 0.00 594435 Symbol#to_s   3.23 15.68 0.54 0.00 15.59 41201 Array#each   2.38 0.40 0.40 0.00 0.00 2855 Module#constants

Looks like require is 1/2 speed and that evaluating array blocks(?) has slowed down considerably. I saw chatter about require being an issue in 1.9.1 but the issue was closed.

Doesn't seem to be a Rails issue as much as a Ruby issue.

I have the same issue wrt using autotest. My tests take 3x the time to run with 1.9.2.

-cpr

14

Hi Colin,

I have duplicated your tests using rvm on Ubuntu 10.04, with AMD64, and 3GB RAM, results are below:

> ... > Colin, do you have a sample application? Next, it really depends > on your overall system and Rails app configuration. For example, > if you don't have enough RAM, your system move data from memory > to the disk and vice-versa. This is a huge performance hit. Can you > provide more information?

I have 1GByte RAM and while running the test it shows less than half used and the disk is not rattling. The processor shows 100% utilisation whilst the test is running, with rake being the process using most of it.

I have tried making a new rails 3.0.3 app rails new testruby then using rvm to switch between 1.8.7 p302 and 1.9.2 p136

On each ruby I ran time rake db:migrate a couple of times to let the disk cache settle out then for 1.8.7 I got real 0m2.111s user 0m1.804s sys 0m0.220s

real 0m2.520s user 0m2.100s sys 0m0.340s

and on 1.9.2 real 0m4.098s user 0m3.512s sys 0m0.424s

real 0m0.922s user 0m0.730s sys 0m0.150s

I also tried rake test and got, on 1.8.7

I ran rake test and got no output, rake test:benchmark gave the following:

real 0m3.615s user 0m3.104s sys 0m0.316s

Finished in 0.289591 seconds

and on 1.9.2 real 0m6.487s user 0m5.320s sys 0m0.684s

Finished in 0.578807 seconds

It seems as if 1.9.2 takes about twice as long for some reason.

Colin

Paul

15

Update:

Hi Colin,

I have duplicated your tests using rvm on Ubuntu 10.04, with AMD64, and 3GB RAM, results are below:

> > ... > > Colin, do you have a sample application? Next, it really depends > > on your overall system and Rails app configuration. For example, > > if you don't have enough RAM, your system move data from memory > > to the disk and vice-versa. This is a huge performance hit. Can you > > provide more information?

> I have 1GByte RAM and while running the test it shows less than half > used and the disk is not rattling. The processor shows 100% > utilisation whilst the test is running, with rake being the process > using most of it.

> I have tried making a new rails 3.0.3 app > rails new testruby > then using rvm to switch between 1.8.7 p302 and 1.9.2 p136

> On each ruby I ran > time rake db:migrate > a couple of times to let the disk cache settle out then for 1.8.7 I got > real 0m2.111s > user 0m1.804s > sys 0m0.220s

real 0m2.520s user 0m2.100s sys 0m0.340s

> and on 1.9.2 > real 0m4.098s > user 0m3.512s > sys 0m0.424s

real 0m0.922s user 0m0.730s sys 0m0.150s

> I also tried rake test and got, on 1.8.7

I ran rake test and got no output, rake test:benchmark gave the following:

> real 0m3.615s > user 0m3.104s > sys 0m0.316s

Finished in 0.289591 seconds

real 0m4.363s user 0m3.390s sys 0m0.540s

> and on 1.9.2 > real 0m6.487s > user 0m5.320s > sys 0m0.684s

Finished in 0.578807 seconds

real 0m7.211s user 0m5.810s sys 0m0.940s

16

Hi Colin,

I have duplicated your tests using rvm on Ubuntu 10.04, with AMD64, and 3GB RAM, results are below:

> ... > Colin, do you have a sample application? Next, it really depends > on your overall system and Rails app configuration. For example, > if you don't have enough RAM, your system move data from memory > to the disk and vice-versa. This is a huge performance hit. Can you > provide more information?

I have 1GByte RAM and while running the test it shows less than half used and the disk is not rattling. The processor shows 100% utilisation whilst the test is running, with rake being the process using most of it.

I have tried making a new rails 3.0.3 app rails new testruby then using rvm to switch between 1.8.7 p302 and 1.9.2 p136

On each ruby I ran time rake db:migrate a couple of times to let the disk cache settle out then for 1.8.7 I got real 0m2.111s user 0m1.804s sys 0m0.220s

real 0m2.520s user 0m2.100s sys 0m0.340s

and on 1.9.2 real 0m4.098s user 0m3.512s sys 0m0.424s

real 0m0.922s user 0m0.730s sys 0m0.150s

So you are getting 1.9.2 _faster_ than 1.8.7 for db:migrate?

17

> Hi Colin,

> I have duplicated your tests using rvm on Ubuntu 10.04, with AMD64, > and 3GB RAM, results are below:

>> > ... >> > Colin, do you have a sample application? Next, it really depends >> > on your overall system and Rails app configuration. For example, >> > if you don't have enough RAM, your system move data from memory >> > to the disk and vice-versa. This is a huge performance hit. Can you >> > provide more information?

>> I have 1GByte RAM and while running the test it shows less than half >> used and the disk is not rattling. The processor shows 100% >> utilisation whilst the test is running, with rake being the process >> using most of it.

>> I have tried making a new rails 3.0.3 app >> rails new testruby >> then using rvm to switch between 1.8.7 p302 and 1.9.2 p136

>> On each ruby I ran >> time rake db:migrate >> a couple of times to let the disk cache settle out then for 1.8.7 I got >> real 0m2.111s >> user 0m1.804s >> sys 0m0.220s

> real 0m2.520s > user 0m2.100s > sys 0m0.340s

>> and on 1.9.2 >> real 0m4.098s >> user 0m3.512s >> sys 0m0.424s

> real 0m0.922s > user 0m0.730s > sys 0m0.150s

So you are getting 1.9.2 _faster_ than 1.8.7 for db:migrate?

Yep I was...

however:

I now get (1.9.2p136):

real 4.239s user 3.600s sys 0.460s

I've just checked back over the shell output, and I missed an error message earlier on (I hadn't run bundle install), so those test results (1.9.2) should be ignored - apologies to all for that. (In my defence I'm just recovering from major 'man-flu', first day up and about today, and rvm is a new install today :))

18

I am also getting the slow startup of rake, which impacts development using autotest.

I'm running 1.9.2 on a Mac, and it seems to be taking a lot longer than I ever remember it taking.

I didn't yet run benchmarks, seems like they would be very similar to what you guys were seeing.

- Anthony

19

Seems pretty consistent. Is anyone NOT seeing these results? It's starting to look like this is the reality of Rails on 1.9.2. Is this simply a known Rails performance regression from 1.8 to 1.9? If so, it removes a great deal of my desire to upgrade. Perhaps we should take this to rails-core.

20

Done.

http://permalink.gmane.org/gmane.comp.lang.ruby.rails.core/14754

Colin