From: court3nay <court3nay@...>
Date: 2009-04-28T13:00:05+09:00
Subject: Re: Weird performance issue

On Apr 16, 5:39 pm, Ryan Davis <ryand-r...@zenspider.com> wrote:
> On Apr 16, 2009, at 16:25 ,court3naywrote:
>
>
>
> > 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
>
> 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"
On the fast VM, 34 gems:

$ cat labs.txt | cut -f 2 -d : | sort | uniq -c | sort -rn
   4044 /usr/lib64/ruby/1.8/x86_64-linux/rbconfig.rb
   1510 /usr/lib/ruby/site_ruby/1.8/rubygems/specification.rb
   1160 /usr/lib/ruby/1.8/net/http.rb
    388 /usr/lib/ruby/1.8/uri/generic.rb
    335 /usr/lib/ruby/site_ruby/1.8/rubygems.rb
    273 /usr/lib/ruby/1.8/uri/common.rb
    249 /usr/lib/ruby/site_ruby/1.8/rubygems/user_interaction.rb
    238 /usr/lib/ruby/1.8/net/protocol.rb
    175 /usr/lib/ruby/site_ruby/1.8/rubygems/version.rb
    156 /usr/lib/ruby/site_ruby/1.8/rubygems/source_index.rb
    154 /usr/lib/ruby/site_ruby/1.8/rubygems/requirement.rb
    125 /usr/lib/ruby/site_ruby/1.8/rubygems/exceptions.rb
    108 /usr/lib/ruby/1.8/uri/ldap.rb
    100 /usr/lib/ruby/1.8/uri/mailto.rb
     90 /usr/lib/ruby/site_ruby/1.8/rubygems/remote_fetcher.rb
     72 /usr/lib/ruby/site_ruby/1.8/rubygems/spec_fetcher.rb
     66 /usr/lib/ruby/site_ruby/1.8/rubygems/platform.rb
     59 /usr/lib/ruby/1.8/uri/ftp.rb
     56 /usr/lib/ruby/site_ruby/1.8/rubygems/dependency.rb
     51 /usr/lib/ruby/1.8/uri.rb
     42 /usr/lib/ruby/1.8/timeout.rb
     33 /usr/lib/ruby/site_ruby/1.8/rubygems/builder.rb
     27 /usr/lib/ruby/1.8/uri/http.rb
     26 /usr/lib/ruby/site_ruby/1.8/rubygems/gem_path_searcher.rb
     24 /usr/lib/ruby/site_ruby/1.8/rubygems/defaults.rb
     15 /usr/lib/ruby/1.8/uri/https.rb
     12 /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb
      4 /usr/lib/ruby/site_ruby/1.8/rubygems/rubygems_version.rb
      4 /usr/lib/ruby/1.8/thread.rb
      3 -e
      1 /usr/lib64/ruby/1.8/x86_64-linux/zlib.so
      1 /usr/lib64/ruby/1.8/x86_64-linux/thread.so
      1 /usr/lib64/ruby/1.8/x86_64-linux/stringio.so
      1 /usr/lib64/ruby/1.8/x86_64-linux/socket.so

On the slow VM, 12 gems: (I'm using ruby-enterprise on this in an
attempt to see if it's built better. It ain't)

  13872 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
specification.rb
  12120 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
version.rb
   3802 /opt/ruby-enterprise/lib/ruby/1.8/x86_64-linux/rbconfig.rb
   3173 /opt/ruby-enterprise/lib/ruby/1.8/fileutils.rb
   1329 /opt/ruby-enterprise/lib/ruby/1.8/date.rb
   1266 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
requirement.rb
    892 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
gem_path_searcher.rb
    878 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
source_index.rb
    847 /opt/ruby-enterprise/lib/ruby/1.8/yaml/tag.rb
    837 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems.rb
    323 /opt/ruby-enterprise/lib/ruby/1.8/date/format.rb
    292 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
dependency.rb
    249 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
user_interaction.rb
    236 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
config_file.rb
    219 (eval)
    172 /opt/ruby-enterprise/lib/ruby/1.8/yaml/rubytypes.rb
    156 /opt/ruby-enterprise/lib/ruby/1.8/rational.rb
    125 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
exceptions.rb
    124 /opt/ruby-enterprise/lib/ruby/1.8/yaml/types.rb
    121 /opt/ruby-enterprise/lib/ruby/1.8/yaml.rb
     95 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
defaults.rb
     65 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
platform.rb
     44 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/
rails-2.3.2.gemspec
     44 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/mime-
types-1.16.gemspec
     43 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/
tinder-1.2.0.gemspec
     43 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/
passenger-2.2.0.gemspec
     41 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/sqlite3-
ruby-1.2.4.gemspec
     41 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/rubygems-
update-1.3.2.gemspec
     40 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/
rake-0.8.4.gemspec
     40 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/
rack-0.9.1.gemspec
     40 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/
fastthread-1.0.7.gemspec
     40 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/
activeresource-2.3.2.gemspec
     40 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/
activerecord-2.3.2.gemspec
     39 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/
hpricot-0.8.1.gemspec
     39 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/
actionpack-2.3.2.gemspec
     39 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/
actionmailer-2.3.2.gemspec
     39 /opt/ruby-enterprise/lib/ruby/1.8/yaml/basenode.rb
     38 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
custom_require.rb
     36 /opt/ruby-enterprise/lib/ruby/gems/1.8/specifications/
activesupport-2.3.2.gemspec
     34 /opt/ruby-enterprise/lib/ruby/1.8/yaml/stream.rb
     32 /opt/ruby-enterprise/lib/ruby/1.8/yaml/error.rb
     30 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
builder.rb
     29 /opt/ruby-enterprise/lib/ruby/1.8/yaml/ypath.rb
     21 /opt/ruby-enterprise/lib/ruby/1.8/yaml/syck.rb
     17 /opt/ruby-enterprise/lib/ruby/1.8/yaml/constants.rb
      5 /opt/ruby-enterprise/lib/ruby/site_ruby/1.8/rubygems/
rubygems_version.rb
      4 /opt/ruby-enterprise/lib/ruby/1.8/thread.rb
      3 -e
      1 /opt/ruby-enterprise/lib/ruby/1.8/x86_64-linux/thread.so
      1 /opt/ruby-enterprise/lib/ruby/1.8/x86_64-linux/syck.so
      1 /opt/ruby-enterprise/lib/ruby/1.8/x86_64-linux/stringio.so
      1 /opt/ruby-enterprise/lib/ruby/1.8/x86_64-linux/etc.so

So, lots more calls to specification.rb and version.rb ...