On Apr 27, 2009, at 21:20, court3nay wrote: > On Apr 27, 8:56 pm, court3nay <court3... / gmail.com> wrote: >> On Apr 16, 5:39 pm, Ryan Davis <ryand-r... / zenspider.com> wrote: >>> On Apr 16, 2009, at 16:25 ,court3nay wrote: >> >>>> Hey, I'm debugging a weird performance issue. I have two VMs on the >>>> same server running the same OS (arch linux) and the same version >>>> of >>>> "enterprise" Ruby (ruby 1.8.6 (2008-08-08 patchlevel 286) [x86_64- >>>> linux]). >>>> >>>> On one machine, I get these numbers >>>> >>>> irb(main):004:0> Benchmark.realtime { require 'rubygems' } >>>> => 0.0482780933380127 >>>> irb(main):005:0> Benchmark.realtime { require 'tinder' } >>>> => 0.395686149597168 >>>> >>>> On the other, >>>> >>>> irb(main):002:0> Benchmark.realtime { require 'rubygems' } >>>> => 1.20596885681152 >>>> irb(main):003:0> Benchmark.realtime { require 'tinder' } >>>> => 5.7661280632019 >>> >>> same number of gems on both slices? >>> >>> % gem list | wc -l are you sure that `gem` and `ruby` match? >>> you can also do something really gross like: >>> >>> % ruby -rtracer -e 'require "rubygems"' > server1.txt >> >>> I don't think you should necessarily diff the two, but looking at >>> rough things like # of lines should start to explain stuff. >>> Something >>> maybe like: >> >>> % ruby -rtracer -e 'require "rubygems"' | cut -f 2 -d : | occur | >>> head >>> 41672: /Library/Ruby/Site/1.8/rubygems/specification.rb >>> 38352: /Library/Ruby/Site/1.8/rubygems/version.rb >>> 3865: /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/ >>> lib/ >>> ruby/1.8/universal-darwin9.0/rbconfig.rb >>> 3544: /Library/Ruby/Site/1.8/rubygems/requirement.rb >>> 3491: /Library/Ruby/Site/1.8/rubygems/gem_path_searcher.rb >>> 3173: /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/ >>> lib/ >>> ruby/1.8/fileutils.rb >>> 2329: /Library/Ruby/Site/1.8/rubygems/source_index.rb >>> 1213: /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/ >>> lib/ >>> ruby/1.8/date.rb >>> 1087: /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/ >>> lib/ >>> ruby/1.8/optparse.rb >>> 847: /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/ >>> lib/ >>> ruby/1.8/yaml/tag.rb >> >>> (occur is a simple script I wrote to aggregate input... I loves it) >> >> OK, here we go. I think your "occur" script is vaguely the same as >> "sort | uniq -c | sort -rn" > > I ran a profile, too. > > Fast VM: > > $ ruby -r profile -e 'require "rubygems"' > > % cumulative self self total > time seconds seconds calls ms/call ms/call name > 33.33 0.05 0.05 57 0.88 9.12 Kernel.require > 13.33 0.07 0.02 204 0.10 0.10 String#gsub! > 6.67 0.08 0.01 20 0.50 0.50 Module#protected > 6.67 0.09 0.01 40 0.25 0.25 > Module#attr_reader > 6.67 0.10 0.01 144 0.07 0.07 Kernel.dup > 6.67 0.11 0.01 443 0.02 0.02 Hash#[]= > 6.67 0.12 0.01 1 10.00 20.00 Hash#each > 6.67 0.13 0.01 9 1.11 1.11 > Gem::Specification#array_attribute > 6.67 0.14 0.01 19 0.53 0.53 > Regexp#initialize > 6.67 0.15 0.01 37 0.27 0.27 > Module#attr_accessor This profile doesn't find a single gem, try: ruby -rubygems -e 'p Gem.source_index.size' In fact, it didn't try to even load any gems. There's no call to Gem::SourceIndex#load_gems_in and no calls to Gem::SourceIndex#load_specification. Even if you don't have any gems installed and have nuked your repo, you should call #load_gems_in. There seems to be something wrong with this RubyGems. > Slow VM: > > ruby -r profile -e 'require "rubygems"' > % cumulative self self total > time seconds seconds calls ms/call ms/call name > 1.49 5.97 0.14 14 10.00 397.86 > Gem::SourceIndex#load_specification This profile found 14 gems, but has one fewer require. Also, is RUBYOPT or RUBYLIB set? Also: > $ ruby -r profile -e 'require "rubygems"' > > % cumulative self self total > time seconds seconds calls ms/call ms/call name > 33.33 0.05 0.05 57 0.88 9.12 Kernel.require I ran something like this: $ rm -rf ~/tmp/gems; GEM_HOME=~/tmp/gems GEM_PATH=~/tmp/gems ruby -r profile -e 'require "rubygems"' % cumulative self self total time seconds seconds calls ms/call ms/call name 27.59 0.08 0.08 54 1.48 14.81 Kernel.require You seem to have called require more times than me, can you diff against: $ ruby -e 'require "rubygems"; puts $LOADED_FEATURES.sort.join("\n")' date.rb date/format.rb etc.bundle fileutils.rb rational.rb rbconfig.rb rubygems.rb rubygems/builder.rb rubygems/config_file.rb rubygems/custom_require.rb rubygems/defaults.rb rubygems/dependency.rb rubygems/exceptions.rb rubygems/gem_path_searcher.rb rubygems/platform.rb rubygems/requirement.rb rubygems/rubygems_version.rb rubygems/source_index.rb rubygems/specification.rb rubygems/user_interaction.rb rubygems/version.rb stringio.bundle syck.bundle thread.bundle thread.rb yaml.rb yaml/basenode.rb yaml/constants.rb yaml/error.rb yaml/rubytypes.rb yaml/stream.rb yaml/syck.rb yaml/tag.rb yaml/types.rb yaml/ypath.rb