Bug #3726
closedrequire degradation from 1.9.1
Description
=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
Updated by rogerdpack (Roger Pack) about 14 years ago
=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
Updated by raggi (James Tucker) about 14 years ago
=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
Updated by raggi (James Tucker) about 14 years ago
=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
Updated by funny_falcon (Yura Sokolov) about 14 years ago
=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
Updated by funny_falcon (Yura Sokolov) about 14 years ago
=begin
Well, faster-rubygems seems to do the job. Thank you, Roger.
=end
Updated by raggi (James Tucker) about 14 years ago
=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
Updated by funny_falcon (Yura Sokolov) about 14 years ago
=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
Updated by naruse (Yui NARUSE) over 13 years ago
- Status changed from Open to Closed
On 1.9.3, require gets faster than 1.9.2.
So I close this as duplicated.