Weird performance issue

C

court3nay

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?
 
R

Ryan Davis

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
Click to expand...

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)
 
R

Robert Klemme

2009/4/17 Ryan Davis said:
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
Click to expand...

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:
Click to expand...

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
 
P

Peter Booth

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

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
Click to expand...

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)
Click to expand...
 
C

court3nay

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]).
Click to expand...
On one machine, I get these numbers
Click to expand...
irb(main):004:0> Benchmark.realtime { require 'rubygems' }
=> 0.0482780933380127
irb(main):005:0> Benchmark.realtime { require 'tinder' }
=> 0.395686149597168
Click to expand...
On the other,
Click to expand...
irb(main):002:0> Benchmark.realtime { require 'rubygems' }
=> 1.20596885681152
irb(main):003:0> Benchmark.realtime { require 'tinder' }
=> 5.7661280632019
Click to expand...

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)
Click to expand...

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 ...
 
C

court3nay

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
Click to expand...
Click to expand...
same number of gems on both slices?
Click to expand...
% gem list | wc -l
Click to expand...
you can also do something really gross like:
Click to expand...
% ruby -rtracer -e 'require "rubygems"' > server1.txt
Click to expand...
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:
Click to expand...
% 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
Click to expand...
(occur is a simple script I wrote to aggregate input... I loves it)
Click to expand...

OK, here we go. I think your "occur" script is vaguely the same as
"sort | uniq -c | sort -rn"
Click to expand...

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
 
R

Roger Pack

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:
Click to expand...

I'd use dstat to try and see what is being hammered--are you IO bound or
cpu bound?
cheers.
-=r
 
B

Brian Candler

court3nay said:
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
Click to expand...

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.
 
R

Ryan Davis

I ran a profile, too.
Click to expand...

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.
 
E

Eric Hodel

On Apr 16, 2009, at 16:25 ,court3nay wrote:
Click to expand...
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
Click to expand...
Click to expand...
Click to expand...

are you sure that `gem` and `ruby` match?
OK, here we go. I think your "occur" script is vaguely the same as
"sort | uniq -c | sort -rn"
Click to expand...

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
Click to expand...

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
Click to expand...

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
Click to expand...

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
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Similar Threads

Weird Behavior with Rays in C and OpenGL 4
bsearch.rb 0
gems and custom_require problem for ruby(1.9.2dev)/rubygems(1.3.6)installed in $HOME 0
Net-Ping Issue on Windows 0
Ruby 1.9.2 require issue 2
RubyInline and Digest::Base error 0
Watir issue with AutoIt on Vista 64 bit 0
Digest::SHA256.hexdigest failing with the digest/sha1 2

Members online

No members online now.
Total: 1,050 (members: 0, guests: 1,050)
Robots: 46

Forum statistics

Threads
474,175
Messages
2,570,942
Members
47,489
Latest member
BrigidaD91

Latest Threads

Top