Extremely slow start up with ruby 1.9.1 vs 1.8.7

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.

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.

Colin

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

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

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

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

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

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


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

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

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

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

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

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

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?

> 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 :))

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

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.

Done.

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

Colin