Forum: Ruby Weird performance issue

Announcement (2017-05-07): www.ruby-forum.com is now read-only since I unfortunately do not have the time to support and maintain the forum any more. Please see rubyonrails.org/community and ruby-lang.org/en/community for other Rails- und Ruby-related community platforms.
court3nay (Guest)
on 2009-04-17 03:26
(Received via mailing list)
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

Which is crazy.  Over an order of magnitude.  My question is, how can
I trace what is taking all the time?  It's not just requiring
libraries -- I can reproduce with pure math.  On the "fast" machine:

irb(main):007:0> Benchmark.realtime { 1000.times { 10 ** rand
(1000) } }
=> 0.00720095634460449

On the "slow" machine....

Benchmark.realtime { 1000.times { 10 ** rand(1000) } }
=> 0.142554998397827

Any ideas?
Ryan D. (Guest)
on 2009-04-17 04:39
(Received via mailing list)
On Apr 16, 2009, at 16:25 , court3nay wrote:

> => 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)
Robert K. (Guest)
on 2009-04-17 11:04
(Received via mailing list)
2009/4/17 Ryan D. <removed_email_address@domain.invalid>:
>> irb(main):004:0> Benchmark.realtime { require 'rubygems' }
>
>
If that does not work then "strace" might be an option as well.  That
usually also contains timestamps and you might be able to spot a
syscall which is taking a lot of time.

Kind regards

robert
Peter B. (Guest)
on 2009-04-17 17:26
(Received via mailing list)
The first step is to see whether the problem is in the Ruby
infrastructure or underneath.

The easiest way to do that is to run a Linux CPU benchmark on each and
see whether you observe the same difference. Unixbench, lmbench or the
Java volano benchmark would work.

1. If its infrastructure:
  check your VM is using same cap and weight, same filesystem, etc ...
2. If its ruby
  run lsof on your test process and see whether each are opening the
same libraries, then strace if necessary


Peter
court3nay (Guest)
on 2009-04-28 08:01
(Received via mailing list)
On Apr 16, 5:39 pm, Ryan D. <removed_email_address@domain.invalid> wrote:
>
> > => 5.7661280632019
> rough things like # of lines should start to explain stuff. Something  
> 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 ...
court3nay (Guest)
on 2009-04-28 08:21
(Received via mailing list)
On Apr 27, 8:56 pm, court3nay <removed_email_address@domain.invalid> wrote:
>
> > > => 1.20596885681152
>
> >   3491: /Library/Ruby/Site/1.8/rubygems/gem_path_searcher.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
  0.00     0.15      0.00       22     0.00     0.00  Module#include
  0.00     0.15      0.00      165     0.00     0.00  Class#inherited
  0.00     0.15      0.00        8     0.00     0.00
Module#class_eval
  0.00     0.15      0.00       22     0.00     0.00
Module#append_features
  0.00     0.15      0.00        1     0.00     0.00  Hash#merge!
  0.00     0.15      0.00       31     0.00     0.00  Kernel.freeze
  0.00     0.15      0.00        9     0.00     0.00  Fixnum#-
  0.00     0.15      0.00        2     0.00     0.00  Array#join
  0.00     0.15      0.00        1     0.00     0.00  Time#gmt_offset
  0.00     0.15      0.00      829     0.00     0.00
Module#method_added
  0.00     0.15      0.00       54     0.00     0.00  Module#private
  0.00     0.15      0.00       25     0.00     0.40  Class#new
  0.00     0.15      0.00        1     0.00     0.00  Kernel.extend
  0.00     0.15      0.00        2     0.00     0.00
Gem::Version#normalize
  0.00     0.15      0.00       12     0.00     0.00
Gem::Specification#overwrite_accessor
  0.00     0.15      0.00        5     0.00     0.00  String#to_i
  0.00     0.15      0.00        1     0.00     0.00
Object#initialize
  0.00     0.15      0.00        5     0.00     0.00  Module#===
  0.00     0.15      0.00       12     0.00     0.00
Module#remove_method
  0.00     0.15      0.00        2     0.00     0.00
Gem::Requirement#default
  0.00     0.15      0.00        2     0.00     0.00
Gem::Requirement#initialize
  0.00     0.15      0.00        2     0.00     0.00
Gem::Version#build_array_from_version_string
  0.00     0.15      0.00        1     0.00     0.00  Hash#keys
  0.00     0.15      0.00        2     0.00     0.00
Gem::Version#correct?
  0.00     0.15      0.00        1     0.00     0.00  Kernel.caller
  0.00     0.15      0.00        1     0.00     0.00  Fixnum#%
  0.00     0.15      0.00        2     0.00     0.00  Kernel.class
  0.00     0.15      0.00        7     0.00     1.43
Gem::Specification#required_attribute
  0.00     0.15      0.00        8     0.00     0.00
Module#private_class_method
  0.00     0.15      0.00       91     0.00     0.00  Symbol#to_s
  0.00     0.15      0.00       30     0.00     0.00  String#intern
  0.00     0.15      0.00        1     0.00     0.00
Module#extend_object
  0.00     0.15      0.00        2     0.00     0.00  Array#[]
  0.00     0.15      0.00        4     0.00     0.00  String#to_s
  0.00     0.15      0.00        1     0.00    20.00  Hash#each_value
  0.00     0.15      0.00        2     0.00     0.00
Module#attr_writer
  0.00     0.15      0.00        1     0.00     0.00  String#split
  0.00     0.15      0.00        1     0.00     0.00  Time#initialize
  0.00     0.15      0.00        1     0.00     0.00  Module#extended
  0.00     0.15      0.00        2     0.00     0.00
Gem::Requirement#parse
  0.00     0.15      0.00        2     0.00     0.00  Fixnum#==
  0.00     0.15      0.00        8     0.00     0.00  Regexp#quote
  0.00     0.15      0.00        1     0.00     0.00
Gem.marshal_version
  0.00     0.15      0.00      174     0.00     0.00
Kernel.singleton_method_added
  0.00     0.15      0.00        2     0.00     0.00
Gem::Version#version=
  0.00     0.15      0.00        1     0.00     0.00  Fixnum#+
  0.00     0.15      0.00        4     0.00     0.00  Array#each
  0.00     0.15      0.00        3     0.00     0.00
Module#module_function
  0.00     0.15      0.00      204     0.00     0.10  Config.expand
  0.00     0.15      0.00        1     0.00     0.00  Time#at
  0.00     0.15      0.00        2     0.00     0.00  Comparable.<
  0.00     0.15      0.00        5     0.00     0.00  Array#map
  0.00     0.15      0.00        1     0.00     0.00  Array#collect
  0.00     0.15      0.00       12     0.00     0.00
Module#method_removed
  0.00     0.15      0.00        2     0.00     0.00  Array#length
  0.00     0.15      0.00       76     0.00     0.00  Array#<<
  0.00     0.15      0.00        2     0.00     0.00  Time#to_i
  0.00     0.15      0.00        1     0.00     0.00  Regexp#=~
  0.00     0.15      0.00        1     0.00     0.00
Exception#initialize
  0.00     0.15      0.00        1     0.00     0.00
Module#instance_method
  0.00     0.15      0.00        1     0.00     0.00  String#chomp!
  0.00     0.15      0.00        4     0.00     0.00
Gem::Specification#attribute_alias_singular
  0.00     0.15      0.00        9     0.00     0.00
Module#module_eval
  0.00     0.15      0.00       66     0.00     0.00  String#[]
  0.00     0.15      0.00        1     0.00     0.00  Regexp#to_s
  0.00     0.15      0.00        2     0.00     0.00  String#<=>
  0.00     0.15      0.00       11     0.00     0.00  NilClass#nil?
  0.00     0.15      0.00        1     0.00     0.00
Gem::Specification#read_only
  0.00     0.15      0.00      144     0.00     0.00
String#initialize_copy
  0.00     0.15      0.00       20     0.00     0.00
Module#define_method
  0.00     0.15      0.00       80     0.00     0.00  Hash#[]
  0.00     0.15      0.00       10     0.00     0.00  Kernel.nil?
  0.00     0.15      0.00       21     0.00     0.48
Gem::Specification#attribute
  0.00     0.15      0.00        2     0.00     0.00  String#strip
  0.00     0.15      0.00        1     0.00     0.00  Time#now
  0.00     0.15      0.00        9     0.00     0.00  Hash#default
  0.00     0.15      0.00        1     0.00     0.00
Exception#backtrace
  0.00     0.15      0.00        4     0.00     0.00  String#+
  0.00     0.15      0.00        5     0.00     0.00  Module#public
  0.00     0.15      0.00        7     0.00     0.00  Kernel.lambda
  0.00     0.15      0.00        2     0.00     0.00
Gem::Specification#attributes
  0.00     0.15      0.00        2     0.00     0.00  File#dirname
  0.00     0.15      0.00        1     0.00     0.00  Time#-
  0.00     0.15      0.00        3     0.00     0.00  String#scan
  0.00     0.15      0.00        2     0.00     0.00  String#==
  0.00     0.15      0.00        4     0.00     0.00  Regexp#===
  0.00     0.15      0.00        1     0.00     0.00
Exception#set_backtrace
  0.00     0.15      0.00       22     0.00     0.00  Module#included
  0.00     0.15      0.00        2     0.00     0.00
Gem::Version#initialize
  0.00     0.15      0.00        7     0.00     0.00  Array#first
  0.00     0.15      0.00        5     0.00     0.00  Fixnum#to_s
  0.00     0.15      0.00        1     0.00   150.00  #toplevel

Slow VM:

ruby -r profile -e 'require "rubygems"'
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 13.95     1.31      1.31       90    14.56    95.33  Array#each
 10.01     2.25      0.94       56    16.79   281.43  Kernel.require
  5.22     2.74      0.49      784     0.62     0.83  Kernel.===
  4.47     3.16      0.42      335     1.25     1.40
Gem::Version::Part#initialize
  4.15     3.55      0.39      121     3.22    10.58
Gem::Version#normalize
  2.98     3.83      0.28      499     0.56    30.44  Class#new
  2.77     4.09      0.26       14    18.57   381.43  Kernel.eval
  2.13     4.29      0.20      194     1.03     1.55  String#gsub!
  2.13     4.49      0.20      129     1.55     2.02
Module#module_eval
  2.02     4.68      0.19     1149     0.17     0.17  Module#===
  1.92     4.86      0.18       79     2.28     2.78
Gem::Version#correct?
  1.81     5.03      0.17      858     0.20     0.20  Kernel.==
  1.81     5.20      0.17     1012     0.17     0.17
Module#method_added
  1.81     5.37      0.17       79     2.15    17.34
Gem::Version#initialize
  1.70     5.53      0.16       79     2.03    12.41
Gem::Version#version=
  1.60     5.68      0.15      410     0.37     0.46  Kernel.dup
  1.60     5.83      0.15        4    37.50   195.00
Kernel.gem_original_require
  1.49     5.97      0.14       14    10.00   397.86
Gem::SourceIndex#load_specification
  1.38     6.10      0.13       14     9.29    20.00
Gem::Version#balance
  1.38     6.23      0.13      194     0.67     2.22  Config.expand
  1.38     6.36      0.13      147     0.88     7.28  Array#map
  1.28     6.48      0.12      121     0.99     6.53
Gem::Version#parse_parts_from_version_string
  1.17     6.59      0.11       35     3.14    15.43
Gem::Requirement#create
  1.17     6.70      0.11        3    36.67    66.67  Hash#each
  0.96     6.79      0.09      502     0.18     0.18  Hash#[]=
  0.96     6.88      0.09       14     6.43     8.57
Gem::Specification#date=
  0.96     6.97      0.09       24     3.75     3.75
Module#alias_method
  0.85     7.05      0.08       14     5.71   361.43
Gem::Specification#initialize
  0.85     7.13      0.08       24     3.33     7.92  Array#select
  0.75     7.20      0.07        7    10.00    10.00  Gem.user_home
  0.75     7.27      0.07      492     0.14     0.14
Kernel.singleton_method_added
  0.75     7.34      0.07       23     3.04     3.04  Array#flatten
  0.75     7.41      0.07      462     0.15     0.15
Kernel.instance_variable_set
  0.75     7.48      0.07      134     0.52     0.67
Gem::Version::Part#alpha?
  0.64     7.54      0.06       37     1.62    17.03
Gem::Requirement#initialize
  0.64     7.60      0.06       29     2.07     2.07  Kernel.untaint
  0.64     7.66      0.06       37     1.62    15.14
Gem::Requirement#parse
  0.64     7.72      0.06      363     0.17     0.17  String#to_i
  0.64     7.78      0.06      134     0.45     0.60  Module#public
  0.53     7.83      0.05       20     2.50    31.00
Gem::Specification#add_dependency_with_type
  0.53     7.88      0.05       25     2.00     5.60  Module#yaml_as
  0.53     7.93      0.05       33     1.52     1.82
Module#class_eval
  0.53     7.98      0.05       42     1.19     1.90
Module#attr_accessor
  0.53     8.03      0.05      270     0.19     0.19  Array#last
  0.43     8.07      0.04       14     2.86    55.00  Gem::Version#<=>
  0.43     8.11      0.04      121     0.33     0.33  Array#length
  0.43     8.15      0.04       93     0.43     0.43  Kernel.is_a?
  0.32     8.18      0.03       14     2.14     5.00
Gem::GemPathSearcher#matching_files
  0.32     8.21      0.03       28     1.07     1.43
Gem::Version::Part#numeric?
  0.32     8.24      0.03       20     1.50    24.00
Gem::Dependency#initialize
  0.32     8.27      0.03      110     0.27     0.36  Array#include?
  0.32     8.30      0.03       28     1.07     3.57
Gem::Version::Part#<=>
  0.32     8.33      0.03       21     1.43     3.81
Gem::Specification#attribute
  0.32     8.36      0.03      114     0.26     0.26  Array#<<
  0.32     8.39      0.03       10     3.00     7.00
Gem::Specification#array_attribute
  0.32     8.42      0.03       14     2.14     2.14
Gem::Specification#summary=
  0.32     8.45      0.03       59     0.51     0.51
Module#module_function
  0.32     8.48      0.03       14     2.14   139.29
Gem::Specification#assign_defaults
  0.32     8.51      0.03       28     1.07     1.43
Gem::Specification#full_name
  0.32     8.54      0.03        1    30.00    60.00  Array#sort
  0.21     8.56      0.02       49     0.41     0.41  File#join
  0.21     8.58      0.02       14     1.43     4.29
Gem::Specification#full_gem_path
  0.21     8.60      0.02       18     1.11     1.11  Module#include
  0.21     8.62      0.02      112     0.18     0.18  Fixnum#+
  0.21     8.64      0.02       14     1.43     1.43  Time#local
  0.21     8.66      0.02      128     0.16     0.16  Module#private
  0.21     8.68      0.02       12     1.67     2.50
Gem::Specification#overwrite_accessor
  0.21     8.70      0.02        7     2.86     7.14
Gem::Specification#required_attribute
  0.21     8.72      0.02        1    20.00   380.00  Hash#each_value
  0.21     8.74      0.02        1    20.00    60.00
Gem::ConfigFile#initialize
  0.21     8.76      0.02      128     0.16     0.16  Symbol#to_s
  0.21     8.78      0.02       14     1.43    45.00
Gem::Specification#version=
  0.21     8.80      0.02       20     1.00     1.00  Dir#[]
  0.21     8.82      0.02       47     0.43     0.43  Kernel.freeze
  0.21     8.84      0.02      196     0.10     0.10
Array#initialize_copy
  0.21     8.86      0.02       28     0.71     5.00  Enumerable.any?
  0.21     8.88      0.02       56     0.36     8.75
Gem::Version#parts
  0.21     8.90      0.02       14     1.43     5.71
Gem::GemPathSearcher#lib_dirs_for
  0.21     8.92      0.02       38     0.53     0.79  Numeric#nonzero?
  0.21     8.94      0.02      121     0.17     0.17  String#scan
  0.11     8.95      0.01       84     0.12     0.12  Array#size
  0.11     8.96      0.01       15     0.67    34.67
Gem::Specification#add_runtime_dependency
  0.11     8.97      0.01        5     2.00     2.00
Gem::Specification#executables=
  0.11     8.98      0.01       62     0.16     0.16
Kernel.respond_to?
  0.11     8.99      0.01      214     0.05     0.05  String#to_s
  0.11     9.00      0.01        2     5.00     5.00  Gem.default_dir
  0.11     9.01      0.01        4     2.50     2.50
Module#extend_object
  0.11     9.02      0.01       60     0.17     0.17  Symbol#to_i
  0.11     9.03      0.01        4     2.50     2.50
YAML::Syck::Resolver#transfer
  0.11     9.04      0.01       15     0.67     0.67  IO#read
  0.11     9.05      0.01       85     0.12     0.12  String#=~
  0.11     9.06      0.01        1    10.00    10.00
Gem::ConfigFile#handle_arguments
  0.11     9.07      0.01       15     0.67     2.00
FileUtils.private_module_function
  0.11     9.08      0.01      186     0.05     0.05
String#initialize_copy
  0.11     9.09      0.01       22     0.45     1.82
Module#define_method
  0.11     9.10      0.01        5     2.00     8.00
Gem::Specification#attribute_alias_singular
  0.11     9.11      0.01       57     0.18     0.18  String#[]
  0.11     9.12      0.01        1    10.00    10.00  Time#initialize
  0.11     9.13      0.01       16     0.63     1.25
Module#attr_reader
  0.11     9.14      0.01       72     0.14     0.14  Class#inherited
  0.11     9.15      0.01       14     0.71    55.71  Comparable.>=
  0.11     9.16      0.01        3     3.33     3.33  Hash#merge
  0.11     9.17      0.01       28     0.36    11.07
Gem::Version#prerelease?
  0.11     9.18      0.01       14     0.71     0.71
Gem::Specification#installation_path
  0.11     9.19      0.01       29     0.34     0.34  File#exist?
  0.11     9.20      0.01       20     0.50     1.00
Gem.suffix_pattern
  0.11     9.21      0.01      259     0.04     0.04  Fixnum#==
  0.11     9.22      0.01        1    10.00    10.00
Gem::SourceIndex#initialize
  0.11     9.23      0.01       28     0.36     0.36  Kernel.object_id
  0.11     9.24      0.01       14     0.71     0.71
Kernel.block_given?
  0.11     9.25      0.01       40     0.25     0.25
Module#private_class_method
  0.11     9.26      0.01        1    10.00    20.00
YAML::Syck::Parser#load
  0.11     9.27      0.01        5     2.00    24.00
Gem::Specification#add_development_dependency
  0.11     9.28      0.01       25     0.40     0.40  Hash#has_key?
  0.11     9.29      0.01       31     0.32     0.32  Fixnum#<=>
  0.11     9.30      0.01       16     0.62     0.62  Comparable.<
  0.11     9.31      0.01       27     0.37     0.37
Module#attr_writer
  0.11     9.32      0.01       28     0.36     0.36
Gem::Specification#platform
  0.11     9.33      0.01       14     0.71     0.71
Gem::Specification#description=
  0.11     9.34      0.01       14     0.71     7.14
Gem::Specification#required_rubygems_version=
  0.11     9.35      0.01        9     1.11     1.11
Gem::Specification#extra_rdoc_files=
  0.11     9.36      0.01        1    10.00    10.00  Gem.suffixes
  0.11     9.37      0.01       28     0.36     0.36
Kernel.initialize_copy
  0.11     9.38      0.01       25     0.40     0.40  String#dump
  0.11     9.39      0.01       38     0.26     0.26  Fixnum#zero?
  0.00     9.39      0.00        1     0.00     0.00
YAML::Syck::Resolver#use_types_at
  0.00     9.39      0.00        2     0.00    10.00
Gem::ConfigFile#load_file
  0.00     9.39      0.00        3     0.00     0.00
Exception#backtrace
  0.00     9.39      0.00       75     0.00     0.00  Fixnum#*
  0.00     9.39      0.00        3     0.00   270.00
Gem.ensure_gem_subdirectories
  0.00     9.39      0.00        1     0.00  6670.00  Gem.source_index
  0.00     9.39      0.00        1     0.00     0.00  Array#collect
  0.00     9.39      0.00       56     0.00     0.00  String#<=>
  0.00     9.39      0.00        4     0.00     2.50  Kernel.extend
  0.00     9.39      0.00        3     0.00     0.00
Exception#initialize
  0.00     9.39      0.00        2     0.00     0.00  Comparable.>
  0.00     9.39      0.00        3     0.00     0.00  Gem.ruby_engine
  0.00     9.39      0.00        1     0.00     0.00
Gem::ConfigFile#config_file_name
  0.00     9.39      0.00        2     0.00    30.00
Gem.configuration
  0.00     9.39      0.00        2     0.00     0.00
Module#method_undefined
  0.00     9.39      0.00        7     0.00     0.00  Regexp#quote
  0.00     9.39      0.00        2     0.00     0.00
YAML::Syck::Resolver#initialize
  0.00     9.39      0.00       35     0.00     0.00  String#intern
  0.00     9.39      0.00        1     0.00     0.00  Array#uniq
  0.00     9.39      0.00        1     0.00  6830.00  Gem.searcher
  0.00     9.39      0.00        9     0.00     0.00
Gem::Specification#rdoc_options=
  0.00     9.39      0.00        3     0.00     0.00  Array#+
  0.00     9.39      0.00        2     0.00     0.00  Marshal.load
  0.00     9.39      0.00        1     0.00     0.00  Date::Infinity#-
@
  0.00     9.39      0.00        1     0.00     0.00  Gem.find_home
  0.00     9.39      0.00        1     0.00     0.00
Gem::SourceIndex#each
  0.00     9.39      0.00        8     0.00     0.00  Hash#key?
  0.00     9.39      0.00        1     0.00  5700.00
Array#reverse_each
  0.00     9.39      0.00        1     0.00     0.00  Module#autoload
  0.00     9.39      0.00        2     0.00     0.00  Time#to_i
  0.00     9.39      0.00        2     0.00     0.00  Module#attr
  0.00     9.39      0.00        1     0.00     0.00
Module#public_class_method
  0.00     9.39      0.00      108     0.00     0.00  Kernel.class
  0.00     9.39      0.00        2     0.00     0.00  Dir#glob
  0.00     9.39      0.00        1     0.00     0.00  File::Stat#uid
  0.00     9.39      0.00        2     0.00    25.00
Gem::Requirement#default
  0.00     9.39      0.00        1     0.00     0.00  Array#uniq!
  0.00     9.39      0.00        4     0.00     0.00  Module#extended
  0.00     9.39      0.00       61     0.00     0.00  Kernel.Array
  0.00     9.39      0.00        1     0.00    80.00  Gem.default_path
  0.00     9.39      0.00        1     0.00     0.00  Date::Infinity#d
  0.00     9.39      0.00       14     0.00    26.43
Gem::Version#create
  0.00     9.39      0.00        1     0.00     0.00  Hash#clear
  0.00     9.39      0.00        1     0.00     0.00  YAML.resolver
  0.00     9.39      0.00        4     0.00     0.00  Symbol#yaml_new
  0.00     9.39      0.00        1     0.00  6930.00  Gem.find_files
  0.00     9.39      0.00       28     0.00     0.00  String#gsub
  0.00     9.39      0.00        1     0.00     0.00  Time#gmt_offset
  0.00     9.39      0.00       28     0.00     0.00
Gem::Version#to_s
  0.00     9.39      0.00       20     0.00     0.00
Gem::Specification#dependencies
  0.00     9.39      0.00        1     0.00     0.00  Gem.user_dir
  0.00     9.39      0.00        1     0.00     0.00  String#split
  0.00     9.39      0.00       64     0.00     0.00  Kernel.nil?
  0.00     9.39      0.00       10     0.00     0.00  Fixnum#-
  0.00     9.39      0.00       14     0.00     5.00
Gem::GemPathSearcher#matching_file?
  0.00     9.39      0.00       18     0.00     0.00
Module#append_features
  0.00     9.39      0.00        7     0.00    15.71  Date#once
  0.00     9.39      0.00       18     0.00     0.00  Module#included
  0.00     9.39      0.00        1     0.00     0.00  Hash#merge!
  0.00     9.39      0.00        1     0.00     0.00  Time#-
  0.00     9.39      0.00        1     0.00   800.00  Gem.dir
  0.00     9.39      0.00        2     0.00     0.00  Marshal.dump
  0.00     9.39      0.00        2     0.00     0.00  Module#protected
  0.00     9.39      0.00        1     0.00     0.00
Gem::Specification#required_ruby_version=
  0.00     9.39      0.00       11     0.00     0.91
#<YAML::Syck::Resolver:0x158d170>.node_import
  0.00     9.39      0.00        1     0.00     0.00  Enumerable.map
  0.00     9.39      0.00       14     0.00     0.00  Kernel.=~
  0.00     9.39      0.00        3     0.00    36.67
FileUtils.collect_method
  0.00     9.39      0.00        2     0.00     0.00  Etc.getpwuid
  0.00     9.39      0.00        1     0.00   960.00
Gem::SourceIndex#installed_spec_directories
  0.00     9.39      0.00        1     0.00    10.00  Enumerable.find
  0.00     9.39      0.00        1     0.00  6830.00
Gem::GemPathSearcher#initialize
  0.00     9.39      0.00       93     0.00     0.00  String#strip
  0.00     9.39      0.00        4     0.00     0.00  Hash#keys
  0.00     9.39      0.00       14     0.00     6.43
Gem::SourceIndex#add_spec
  0.00     9.39      0.00        1     0.00     0.00
YAML::Syck::Parser#initialize
  0.00     9.39      0.00        2     0.00     0.00  String#index
  0.00     9.39      0.00        1     0.00     0.00
Gem.marshal_version
  0.00     9.39      0.00        1     0.00     0.00
Gem::Specification#read_only
  0.00     9.39      0.00       14     0.00     0.00
Gem::Specification#authors=
  0.00     9.39      0.00        2     0.00  3415.00
Mutex#synchronize
  0.00     9.39      0.00       32     0.00     0.00  Array#pop
  0.00     9.39      0.00        1     0.00    10.00
Gem.win_platform?
  0.00     9.39      0.00        1     0.00     0.00
Kernel.singleton_methods
  0.00     9.39      0.00        1     0.00     0.00  String#chomp!
  0.00     9.39      0.00       37     0.00     0.00  Regexp#===
  0.00     9.39      0.00       29     0.00     0.00  String#==
  0.00     9.39      0.00        3     0.00     0.00
Date::Infinity#initialize
  0.00     9.39      0.00        1     0.00    70.00
Gem::GemPathSearcher#find_all
  0.00     9.39      0.00       42     0.00     0.00  Fixnum#<
  0.00     9.39      0.00       25     0.00     0.80  YAML.tag_class
  0.00     9.39      0.00        1     0.00     0.00  Time#at
  0.00     9.39      0.00       22     0.00     0.00  File#expand_path
  0.00     9.39      0.00      182     0.00     0.00  Hash#[]
  0.00     9.39      0.00        3     0.00     0.00
Hash#initialize_copy
  0.00     9.39      0.00       14     0.00     0.00  Kernel.binding
  0.00     9.39      0.00        7     0.00     0.00  Kernel.lambda
  0.00     9.39      0.00        1     0.00     0.00  YAML.parser
  0.00     9.39      0.00       14     0.00     0.00
Gem::Specification#files=
  0.00     9.39      0.00        1     0.00  5710.00
Gem::SourceIndex#from_gems_in
  0.00     9.39      0.00        1     0.00    20.00  YAML.load
  0.00     9.39      0.00       30     0.00     0.00  File#dirname
  0.00     9.39      0.00       15     0.00     0.00  File#directory?
  0.00     9.39      0.00        1     0.00     0.00
Object#initialize
  0.00     9.39      0.00       62     0.00     0.00  Fixnum#to_s
  0.00     9.39      0.00       12     0.00     0.00
Module#method_removed
  0.00     9.39      0.00        1     0.00     0.00  Gem.clear_paths
  0.00     9.39      0.00        1     0.00    10.00  Time#now
  0.00     9.39      0.00        3     0.00     0.00
Gem::Specification#requirements=
  0.00     9.39      0.00        1     0.00   800.00  Gem.set_home
  0.00     9.39      0.00       14     0.00     7.14  Array#<=>
  0.00     9.39      0.00       17     0.00     0.00  Array#join
  0.00     9.39      0.00        4     0.00     0.00  ENV.[]
  0.00     9.39      0.00        1     0.00  5700.00
Gem::SourceIndex#load_gems_in
  0.00     9.39      0.00        1     0.00  5700.00
Gem::SourceIndex#refresh!
  0.00     9.39      0.00        3     0.00     0.00
Exception#set_backtrace
  0.00     9.39      0.00        1     0.00     0.00
File::Stat#initialize
  0.00     9.39      0.00       12     0.00     0.00
Module#remove_method
  0.00     9.39      0.00        4     0.00     0.00
Gem::Specification#test_files=
  0.00     9.39      0.00        1     0.00     0.00  Fixnum#-@
  0.00     9.39      0.00        1     0.00     0.00  Array#-
  0.00     9.39      0.00      138     0.00     0.00  Array#empty?
  0.00     9.39      0.00        1     0.00  6670.00
Gem::SourceIndex#from_installed_gems
  0.00     9.39      0.00        3     0.00     0.00
Gem::Specification#extensions=
  0.00     9.39      0.00        1     0.00   960.00  Gem.path
  0.00     9.39      0.00        1     0.00     0.00  Fixnum#%
  0.00     9.39      0.00        2     0.00     0.00
Struct#initialize
  0.00     9.39      0.00        1     0.00   820.00  Gem.set_paths
  0.00     9.39      0.00        1     0.00     0.00  Kernel.hash
  0.00     9.39      0.00        7     0.00     0.00  Array#first
  0.00     9.39      0.00        1     0.00  6730.00
Gem::GemPathSearcher#init_gemspecs
  0.00     9.39      0.00        2     0.00     0.00  Array#compact
  0.00     9.39      0.00        1     0.00     0.00
YAML::Syck::Parser#set_resolver
  0.00     9.39      0.00       14     0.00     0.00  NilClass#nil?
  0.00     9.39      0.00       10     0.00     0.00  Hash#default
  0.00     9.39      0.00        1     0.00     0.00
Struct::Passwd#uid
  0.00     9.39      0.00        1     0.00     0.00  Gem.config_file
  0.00     9.39      0.00        1     0.00  9390.00  #toplevel
Roger P. (Guest)
on 2009-04-29 22:19
> Which is crazy.  Over an order of magnitude.  My question is, how can
> I trace what is taking all the time?  It's not just requiring
> libraries -- I can reproduce with pure math.  On the "fast" machine:

I'd use dstat to try and see what is being hammered--are you IO bound or
cpu bound?
cheers.
-=r
Brian C. (Guest)
on 2009-04-30 00:21
court3nay wrote:
> It's not just requiring
> libraries -- I can reproduce with pure math.  On the "fast" machine:
>
> irb(main):007:0> Benchmark.realtime { 1000.times { 10 ** rand
> (1000) } }
> => 0.00720095634460449
>
> On the "slow" machine....
>
> Benchmark.realtime { 1000.times { 10 ** rand(1000) } }
> => 0.142554998397827

Then that rules out rubygems, since under 1.8.6, unless you require
'rubygems' (or have -rubygems in your RUBYOPT) it won't be touched at
all.

Make sure you don't compare just real time, but also CPU time used on
the two machines. If the CPU time is the same but the real time is
vastly different, it could mean that one VM is running a bunch of other
processes (compare load average using 'uptime'), or that one VM is
deprioritised with respect to the other.

I've never heard of "arch linux" (is that a distribution?), but assuming
it comes with the usual bits of code, I'd also suggest running a
comparable benchmark using say Perl. e.g.

$ time perl -e 'for ($i=0;$i<1000000;$i++) {10*10}'

real  0m0.737s
user  0m0.720s
sys  0m0.008s

If the times are vastly different between the two machines, then you
know the problem is nothing to do with ruby and is something to do with
the VM platform.

If the times are identical for Perl but different for Ruby, then
something odd is going on. You can try copying the Ruby from one over to
the other, but that's unlikely to explain the difference if Ruby came
from the distro as a binary, or was the same binary unpacked from a
tarball.

Regards,

Brian.
Ryan D. (Guest)
on 2009-04-30 03:05
(Received via mailing list)
On Apr 27, 2009, at 21:20 , court3nay wrote:

> I ran a profile, too.

looking at your profile on fast and slow shows a ton of differences.
If I ignore the times completely I find this very interesting cluster
at 14 calls on your slow run: http://pastie.org/463189.txt

Basically, it looks like you're not loading any gems on the fast side
at all, despite having roughly the same number of requires. You don't
have any calls to gem_original_require on the fast side for example.
At this point I suspect the fast side is more incorrect than the slow
side, but I dunno.

So, look at `gem env` on both sides, look at `env | egrep "GEM|RUBY"`.
Compare the two and see if you find anything... I think the
suggestions to look at the system with dtrace and the like are going
way too deep way too fast. It's like trying to drink from a firehose.
Eric H. (Guest)
on 2009-04-30 03:22
(Received via mailing list)
On Apr 27, 2009, at 21:20, court3nay wrote:
>>>> On one machine, I get these numbers
>>>> 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?

>>> head
>>>   2329: /Library/Ruby/Site/1.8/rubygems/source_index.rb
>>> (occur is a simple script I wrote to aggregate input... I loves it)
>  %   cumulative   self              self     total
> 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
This topic is locked and can not be replied to.