Extremely slow start up with ruby 1.9.1 vs 1.8.7

[Ben Johnson]

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.
--
Posted via http://www.ruby-forum.com/.

[Micah Geisel]

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

[Colin Law]

On 27 December 2010 22:08, Micah Geisel <li...@ruby-forum.com> wrote:
> 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

[Colin Law]

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

[Colin Law]

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 Law]

On 29 December 2010 20:47, cpr <crose...@gmail.com> wrote:
> Just FYI, I can confirm that I'm seeing the same numbers you are
> (following your gist).
>
> Running Ubuntu 10.4 on Virtual Box on Win 7 x64 on a MacBook Pro i7.

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

[Conrad Taylor]

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

 

--
You received this message because you are subscribed to the Google Groups "Ruby on Rails: Talk" group.
To post to this group, send email to rubyonra...@googlegroups.com.
To unsubscribe from this group, send email to rubyonrails-ta...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/rubyonrails-talk?hl=en.

[Colin Law]

On 29 December 2010 23:18, Conrad Taylor <conr...@gmail.com> wrote:
> ...

> 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

[cpr]

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



On Dec 29, 12:55 pm, Colin Law <clan...@googlemail.com> wrote:

[Conrad Taylor]

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,

[gezope]

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

On 2010 dec. 30, 20:32, Conrad Taylor <conra...@gmail.com> wrote:
> On Thu, Dec 30, 2010 at 7:59 AM, Colin Law <clan...@googlemail.com> wrote:

> > rubyonrails-ta...@googlegroups.com<rubyonrails-talk%2Bunsubscrib e...@googlegroups.com>
> > .

[Colin Law]

On 2 January 2011 01:57, gezope <gez...@gmail.com> wrote:
> 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

> To unsubscribe from this group, send email to rubyonrails-ta...@googlegroups.com.

[cpr]

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

[paul h]

Hi Colin,

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

On Dec 30 2010, 3:59 pm, Colin Law <clan...@googlemail.com> wrote:

> On 29 December 2010 23:18, Conrad Taylor <conra...@gmail.com> wrote:
>
> > ...
> > 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

[paul h]

Update:

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

[Colin Law]

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

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

[paul h]

On Jan 2, 9:52 pm, Colin Law <clan...@googlemail.com> wrote:

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

[Anthony Panozzo]

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

[Micah Geisel]

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.

[Colin Law]

On 8 January 2011 20:55, Micah Geisel <li...@ruby-forum.com> wrote:
> 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

[Jp Jphpsf]

Count me in :/

On ubuntu 10.10 with ruby 1.9.2 and a fresh rails 3.0.3. I created a
cucumber feature with one scenario.

Running cucumber takes about 18 seconds, with 17 seconds spent doing
calls to kernel#require.

See: https://gist.github.com/780747

Now, I installed ruby from ubuntu repos/ppa, which I am not sure it
provided the latest ruby. So I removed everything and installed rvm.
Installed ruby 1.9.2-p136 and had same issue. Then installed ree 1.8.7,
and did not have the issue. It's much faster. I will watch closely the
-core mailing list for a possible resolution, but for now, I will use
ree.

See: https://gist.github.com/781489

[Conrad Taylor]

Hi, in order to put your numbers below into context, can you post the spec for your hardware?

Thanks,

-Conrad

Sent from my iPhone

[Luke Cowell]

This issue in 1.9.2 was affecting me enough that I switched back to 1.8.7, but not without doing a bit of research in to what the problem was.

We see a performance loss in 1.9.2 as it exhibits the correct behaviour when calling require, whereas 1.8.7 is reliant on incorrect semantics that are not acceptable for production use. I was never affected by these incorrect semantics, but I suppose ruby-core has to right these things or accept the long term technical debt.

Something called gem_prelude was added to ruby 1.9 as kludge to address some performance issues.

Ryan David explain (from the ruby-core list):
> It (gem_prelude) was created to address a symptom, namely, that rubygems was slow on some systems (and proportional to the number of gems you have installed).

The good news is: a patch was committed (Jan 14) to ruby that should address some of the performance issues we're seeing. Namely, 1.9.2 users will be able to upgrade to rubygems 1.4 which offers some improved performance.

I don't know when we'll see the next ruby release, but I'm encouraged to see some progress. I'm also encouraged to see that there are members of the ruby-core team actively investigating and addressing these issues.

Luke

[Jp Jphpsf]

Conrad Taylor wrote in post #975240:

> Hi, in order to put your numbers below into context, can you post the
> spec for your hardware?
>
> Thanks,
>
> -Conrad
>

I was running the test on my laptop (core 2 duo 1.86ghz + 2gb ram +
5400rpm hdd). I might run the same test on my desktop (quad core 3.2 ghz
+ 4gb + 10000 rpm drive).

Also, with rvm, I think I can install ruby from head, see if it improves
the performance problem.

[Micah Geisel]

Jp Jphpsf wrote in post #975316:

> Also, with rvm, I think I can install ruby from head, see if it improves
> the performance problem.

I've installed ruby-head via rvm, and updated my gist. It does seem to
be an improvement! Still lagging behind ree, though.

https://gist.github.com/756616

[Roger Pack]

> 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.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

If require is your bottleneck, you can use the faster_require gem:

https://github.com/rdp/faster_require

-r