Feature #3010: slow require gems in ruby 1.9.1

• Status: Closed
• Assignee: drbrain (Eric Hodel)
• Target version: 2.0.0

[JiangMiao (Miao Jiang)]

=begin
ruby 1.9.1 version: ruby 1.9.1p420 (2010-02-04 revision 26571) [i686-linux]
ruby 1.8.7 version: ruby 1.8.7 (2010-01-10 patchlevel 249) [i686-linux]
ruby 1.9 takes a lot time on require 'gemname'

for code: foo.rb
puts $:.size
require 'rubygems'
require 'active_record'
puts $:.size

run: time foo.rb

in 1.9.1 it shows
106
110
real 0m0.905s
user 0m0.777s
sys 0m0.125s

in 1.8.7 it shows
9
21
real 0m0.263s
user 0m0.188s
sys 0m0.060s

And I check $: in code start and after load gem.
in 1.9.1 ruby load the whole rubygems directory on start.
in 1.8.7 ruby only load the nessceary directory for rubygems.
Maybe that is the reason.
=end

[nobu (Nobuyoshi Nakada)]

• Status changed from Open to Assigned
• Assignee set to drbrain (Eric Hodel)

=begin

=end

[rogerdpack (Roger Pack)]

=begin
Have you tried trunk? It would be interesting to use gprof to see what the bottleneck is...

-rp
=end

[JiangMiao (Miao Jiang)]

=begin
Just tried trunk. ruby 1.9.2dev (2010-03-26 trunk 27048) [i686-linux].
The issue still exists.after install and run foo.rb. It shows
105
109

real 0m0.771s
user 0m0.529s
sys 0m0.177s
=end

[rogerdpack (Roger Pack)]

=begin
It appears that you can avoid the use of gem prelude by doing something like

require 'rubygems'
gem 'xxx'
require 'xxx'

If you run it with 1.9.x with "--disable-gems" thusly, for me it gives

1.8.6: 1.0s
1.9.1 --disable-gems: 1.1s
1.9.1 normal: 4s

Hmm.
Appears that the slowdown (here at least) is by calls to Kernel#require taking quite awhile.
http://gist.github.com/344167

On Linux for me, however, 1.8.6 takes 0.3s, 1.9.2 (with gem prelude) takes 0.5s, so not as bad of a difference.

-rp
=end

[drbrain (Eric Hodel)]

=begin
I cannot reproduce with ruby trunk:

$ time ruby19 -v foo.rb
ruby 1.9.2dev (2010-02-09 trunk 26623) [x86_64-darwin10.2.0]
36
/usr/local/lib/ruby/site_ruby/1.9.1/rubygems.rb:65: warning: method redefined; discarding old gem
internal:gem_prelude:15: warning: previous definition of gem was here
lib/rational.rb is deprecated
/usr/local/lib/ruby/gems/1.9.1/gems/activesupport-2.3.5/lib/active_support/core_ext/uri.rb:7:in <top (required)>': warning: URI.escape is obsolete /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-2.3.5/lib/active_support/core_ext/uri.rb:7:in <top (required)>': warning: URI.unescape is obsolete
39

real 0m0.477s
user 0m0.314s
sys 0m0.066s

$ time ruby -v foo.rb
ruby 1.8.7 (2008-08-11 patchlevel 72) [universal-darwin10.0]
11
35

real 0m0.671s
user 0m0.468s
sys 0m0.141s

=end

[drbrain (Eric Hodel)]

=begin
On Mar 25, 2010, at 15:45, Roger Pack wrote:
I cannot reproduce with ruby trunk:

$ time ruby19 -v foo.rb
ruby 1.9.2dev (2010-02-09 trunk 26623) [x86_64-darwin10.2.0]
36
39

real 0m0.477s

From his original post:

in 1.9.1 it shows
106
110

it appears that he has a few more gems installed. I think that is
what helps to reproduce it.

I installed merb on my ruby trunk:

the worst time I got for ruby trunk

$ time ruby19 foo.rb
78
82

real 0m0.579s
user 0m0.382s
sys 0m0.104s

the best time I got for apple ruby 1.8.7

$ time ruby foo.rb
11
35

real 0m0.617s
user 0m0.454s
sys 0m0.120s

=end

[JiangMiao (Miao Jiang)]

=begin
I trace 'active_record' and found Gem::LoadError has 3 different performance.
version,time,percent
1.8.7 0.106,100%
1.9.2 orignal,0.184,174%
1.9.2 cut $: to $:[-9,9],0.158,149%

My ruby 1.8/1.9 compile step:
./configure optflags=-O3
make -j4
make install

New test code:

foo.rb

st=Time.now.to_f
#$:.replace($:[-9,9])
require 'rubygems'
Gem::LoadError
puts Time.now.to_f-st

Test Command:
cat foo.rb;gem environment;(for i in {1..10} ; do ruby foo.rb ; done)|awk '{print $1;s+=$1} END {print "avg:", s/NR}'

Test Result:
1.8.7 0.106 100%
1.9.2 0.184 174%
1.9.2cut 0.158 149%

Test Details:
http://gist.github.com/344366
=end

[dolzenko (Evgeniy Dolzhenko)]

=begin
I'm getting huge performance hit trying to load whole Facets library:

cat 1.rb
gem 'facets', '2.8.4'
require 'facets'

/usr/bin/time -p ruby -v 1.rb
ruby 1.8.7 (2010-01-10 patchlevel 249) [i686-linux]

real 0.39
user 0.03
sys 0.16

/usr/bin/time -p ruby -v 1.rb
ruby 1.9.2dev (2010-04-02 trunk 27162) [i686-linux]

real 6.42
user 2.12
sys 0.92

Profiling results: http://gist.github.com/381991

Seems to be related to this issue?
=end

[rogerdpack (Roger Pack)]

=begin

I'm getting huge performance hit trying to load whole Facets library:

What about if you run it with --disable-gems -- it is fast again?

=end

[rogerdpack (Roger Pack)]

=begin
It appears that with --disable-gems 1.9.2 is still significantly slower than 1.8.6 for loading gems.

on my box, require 'facets'

(~80 gems installed)

1.8.6 1.6s
1.9.3dev 3.7s
1.9.3dev --disable-gems 6.7s

using faster_require (which caches lib locations) 0.6s

Curious...
=end

[sunaku (Suraj Kurapati)]

=begin
Hello,

I am using ruby 1.9.2dev (2010-07-11 revision 28618) [i686-linux]
and this problem seems to be solved in this version. Ruby starts
up just as fast both with and without RubyGems. This is readily
noticeable on my very unpowered computer (slow Intel Atom CPU).

Thanks to the Ruby(Gems) developers and community for fixing this!
=end

[sunaku (Suraj Kurapati)]

=begin
I think this issue can be closed;
the Ruby 1.9.2 release fixed it.
=end

[naruse (Yui NARUSE)]

• Status changed from Assigned to Closed

=begin
thanks for reminder
=end