Feature #3010

slow require gems in ruby 1.9.1

Added by Miao Jiang about 5 years ago. Updated about 4 years ago.

[ruby-core:28954]
Status:Closed
Priority:Normal
Assignee:Eric Hodel

Description

=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

History

#1 Updated by Nobuyoshi Nakada about 5 years ago

  • Assignee set to Eric Hodel
  • Status changed from Open to Assigned

=begin

=end

#2 Updated by Roger Pack about 5 years ago

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

-rp
=end

#3 Updated by Miao Jiang about 5 years ago

=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

#4 Updated by Roger Pack about 5 years ago

=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

#5 Updated by Eric Hodel about 5 years ago

=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
': 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

#6 Updated by Eric Hodel about 5 years ago

=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

#7 Updated by Miao Jiang about 5 years ago

=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

#8 Updated by Evgeniy Dolzhenko about 5 years ago

=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

#9 Updated by Roger Pack about 5 years ago

=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

#10 Updated by Roger Pack about 5 years ago

=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

#11 Updated by Suraj Kurapati almost 5 years ago

=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

#12 Updated by Suraj Kurapati over 4 years ago

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

#13 Updated by Yui NARUSE over 4 years ago

  • Status changed from Assigned to Closed

=begin
thanks for reminder
=end

Also available in: Atom PDF