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
···
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: