Weird performance issue


#1

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?


#2

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)


#3

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


#4

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


#5

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 …


#6

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


#7

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.


#8

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.


#9

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


#10

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