Bug #3726: require degradation from 1.9.1

• Status: Closed
• Assignee: -
• Target version: 1.9.2
• ruby -v: ruby 1.9.2p0 (2010-08-18 revision 29036) [x86_64-linux]

[funny_falcon (Yura Sokolov)]

=begin
I have two simultaneous installation of ruby 1.9.1 and ruby 1.9.2.
There are installed gems ( pg in particular ).

Having file 5.rb containing

require 'pg'

i have following results:

For ruby 1.9.1:

time /opt/ruby1.9.1/bin/ruby1.9 5.rb

real 0m0.086s
user 0m0.056s
sys 0m0.008s

time /opt/ruby1.9.1/bin/ruby1.9 -r profile 5.rb

% cumulative self self total
time seconds seconds calls ms/call ms/call name
100.00 0.03 0.03 2 15.00 25.00 Kernel.require
0.00 0.03 0.00 131 0.00 0.00 Module#method_added
0.00 0.03 0.00 3 0.00 0.00 Class#inherited
0.00 0.03 0.00 1 0.00 0.00 String#=~
0.00 0.03 0.00 13 0.00 0.00 BasicObject#singleton_method_added
0.00 0.03 0.00 4 0.00 0.00 IO#set_encoding
0.00 0.03 0.00 1 0.00 30.00 #toplevel

real 0m0.116s
user 0m0.076s
sys 0m0.020s

For ruby 1.9.2:

time /opt/ruby1.9.2/bin/ruby1.9 5.rb

real 0m0.449s
user 0m0.296s
sys 0m0.048s

time /opt/ruby1.9.2/bin/ruby1.9 -r profile 5.rb

% cumulative self self total
time seconds seconds calls ms/call ms/call name
27.74 0.43 0.43 28 15.36 60.36 Kernel.gem_original_require
5.16 0.51 0.08 3963 0.02 0.02 Hash#default
5.16 0.59 0.08 45 1.78 7.33 Array#each
4.52 0.66 0.07 287 0.24 0.42 String#gsub
3.23 0.71 0.05 897 0.06 0.06 Module#===
3.23 0.76 0.05 11 4.55 45.45 Gem::SourceIndex#load_specification
3.23 0.81 0.05 371 0.13 0.24 Kernel.dup
3.23 0.86 0.05 265 0.19 0.68 RbConfig.expand
2.58 0.90 0.04 126 0.32 10.63 Class#new
2.58 0.94 0.04 374 0.11 0.11 Kernel.initialize_dup
2.58 0.98 0.04 605 0.07 0.07 Kernel.===
1.94 1.01 0.03 585 0.05 0.05 Hash#[]=
1.94 1.04 0.03 31 0.97 4.19 Gem::Requirement#initialize
1.94 1.07 0.03 11 2.73 2.73 IO#read
1.94 1.10 0.03 31 0.97 3.23 Array#map!
1.29 1.12 0.02 531 0.04 0.04 Module#method_added
1.29 1.14 0.02 27 0.74 85.93 Kernel.require
1.29 1.16 0.02 363 0.06 0.06 Kernel.instance_variable_set
1.29 1.18 0.02 59 0.34 0.34 String#scan
1.29 1.20 0.02 64 0.31 0.63 Array#map
1.29 1.22 0.02 21 0.95 1.43 Gem::Specification#attribute
1.29 1.24 0.02 59 0.34 1.53 Gem::Version#initialize
1.29 1.26 0.02 29 0.69 1.03 Array#select
0.65 1.27 0.01 308 0.03 0.03 String#==
0.65 1.28 0.01 159 0.06 0.06 String#to_i
0.65 1.29 0.01 3 3.33 186.67 Mutex#synchronize
0.65 1.30 0.01 26 0.38 0.38 Dir#[]
0.65 1.31 0.01 59 0.17 0.34 Gem::Version#correct?
0.65 1.32 0.01 1 10.00 10.00 Gem.ruby_engine
0.65 1.33 0.01 71 0.14 0.14 String#=~
0.65 1.34 0.01 2 5.00 5.00 Dir#glob
0.65 1.35 0.01 40 0.25 0.25 Module#attr_accessor
0.65 1.36 0.01 176 0.06 0.06 Regexp#=~
0.65 1.37 0.01 9 1.11 1.11 Module#include
0.65 1.38 0.01 8 1.25 1.25 Time#local
0.65 1.39 0.01 100 0.10 0.10 Symbol#to_s
0.65 1.40 0.01 8 1.25 1.25 Comparable.>=
0.65 1.41 0.01 11 0.91 40.91 Kernel.eval
0.65 1.42 0.01 47 0.21 0.21 Kernel.object_id
0.65 1.43 0.01 18 0.56 1.67 Gem::GemPathSearcher#matching_files
0.65 1.44 0.01 1 10.00 10.00 Gem::SourceIndex#search
0.65 1.45 0.01 143 0.07 0.07 Hash#[]
0.65 1.46 0.01 163 0.06 0.06 BasicObject#singleton_method_added
0.00 1.46 0.00 3 0.00 0.00 Gem::Specification#original_name
0.00 1.46 0.00 1 0.00 150.00 Hash#each_value
0.00 1.46 0.00 1 0.00 0.00 Hash#merge!
0.00 1.46 0.00 1 0.00 0.00 Mutex#initialize
.......................................................
0.00 1.46 0.00 1 0.00 0.00 Gem.load_path_insert_index
0.00 1.46 0.00 1 0.00 0.00 Array#insert
0.00 1.46 0.00 1 0.00 10.00 Gem.activate
0.00 1.55 0.00 1 0.00 1550.00 #toplevel

real 0m2.215s
user 0m1.656s
sys 0m0.096s
=end

[rogerdpack (Roger Pack)]

=begin
This is probably because it no longer uses gem_prelude "as much" in 1.9.2
If this is the case and you want the old speed back you could use the faster_rubygems gem.
=end

[raggi (James Tucker)]

=begin
This isn't degradation, it's actually correct behaviour. RubyGems can be (and will be) optimised over time, but the old performance was reliant on very incorrect semantics that are not acceptable for production use.

=end

[raggi (James Tucker)]

=begin
It is also worth noting that this is actually measuring the load time for rubygems itself.

A more accurate representation of the speed of require would come from first loading rubygems explicitly.

require 'rubygems'

Profile { require 'pg' }

Even this has some issues, as the source_index is loaded for the first gem load, and then not required to be loaded each time, so a yet more accurate approach might be something like:

require 'rubygems'
require 'hoe'

Profile { require 'pg' }

As said before, optimisations in this area need to be done in rubygems (and are in progress).

=end

[funny_falcon (Yura Sokolov)]

=begin

It is also worth noting that this is actually measuring the load time for rubygems itself.

I understand it.

I have shell scripts running by schedule, and some cgi scripts, and they runs much slower under 1.9.2 than under 1.9.1 because of this changed behavior.
=end

[funny_falcon (Yura Sokolov)]

=begin
Well, faster-rubygems seems to do the job. Thank you, Roger.
=end

[raggi (James Tucker)]

=begin

On 22 Aug 2010, at 03:25, Yura Sokolov wrote:

Issue #3726 has been updated by Yura Sokolov.

It is also worth noting that this is actually measuring the load time for rubygems itself.

I understood it.

I have shell scripts running by schedule, and some cgi scripts, and they runs much slower under 1.9.2 than under 1.9.1 because of this changed behaviour.

I sympathise with your requirements, however, your requirements do not discount the fact that the prior performance was reliant on a bug.

=end

[funny_falcon (Yura Sokolov)]

=begin
Some bugs are called "features" ;-D
Anyway, faster-rubygems do the job. Perhaps, some ideas from it could be incorparated into the rubygems?
=end

[naruse (Yui NARUSE)]

• Status changed from Open to Closed

On 1.9.3, require gets faster than 1.9.2.
So I close this as duplicated.