Eric Hodel
4/29/2009 11:21:00 PM
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