Skip to content

Instantly share code, notes, and snippets.

@mattdenner
Created June 18, 2011 20:21
Show Gist options
  • Select an option

  • Save mattdenner/1033476 to your computer and use it in GitHub Desktop.

Select an option

Save mattdenner/1033476 to your computer and use it in GitHub Desktop.
Trying to work out why Rubinius takes 30+s longer than MRI 1.8.7

Running a small feature of our application:

time bundle exec cucumber -r features features/small_feature.feature

ruby 1.8.7 (2010-08-16 patchlevel 302) [i686-darwin10.4.3]
  1 scenario (1 passed)
  22 steps (22 passed)
  0m5.951s

  real   0m18.358s
  user   0m15.652s
  sys    0m2.511s

rubinius 1.2.4dev (1.8.7 5cb7a7d2 yyyy-mm-dd JI) [x86_64-apple-darwin10.7.0]
  1 scenario (1 passed)
  22 steps (22 passed)
  0m3.953s

  real   0m47.503s
  user   0m57.764s
  sys    0m2.767s

The extra time is spent starting up the feature. There is a noticeable pause between Using the default profile ... and the display of the tags for the feature. From then on it's quick.

I added some simple debugging to the config/routes.rb file (which is 310 lines long O_O) that output the time taken to process it:

ruby 1.8.7 (2010-08-16 patchlevel 302) [i686-darwin10.4.3]
  Start routing
  Finished in 1.760455

rubinius 1.2.4dev (1.8.7 5cb7a7d2 yyyy-mm-dd JI) [x86_64-apple-darwin10.7.0]
  Start routing
  Finished in 12.397754

Counting (in my head!) the time between seeing Using default profile ... and Start routing, and Finished in .. and the tags for the cucumber feature, is about doubled for Rubinius. I'll dig into that later.

Further simple debugging down in ActionController::Resources reveals that ActionController::Resources#resources is ~10x slower under Rubinius than MRI. As a simple example:

ruby 1.8.7 (2010-08-16 patchlevel 302) [i686-darwin10.4.3]
  Starting resources([:reference_genomes]) ...
  Finished resources([:reference_genomes]) in 0.009815

rubinius 1.2.4dev (1.8.7 5cb7a7d2 yyyy-mm-dd JI) [x86_64-apple-darwin10.7.0]
  Starting resources([:reference_genomes]) ...
  Finished resources([:reference_genomes]) in 0.071018

When I dug a little further it looks like with_options is 4x slower in Rubinius than MRI, but that method is only constructing an ActiveSupport::OptionMerger instance and yielding it. Which lead me to try:

bundle exec ./script/console
ruby-1.8.7-p302 :009 > s=Time.now;(1..10000).each{|_|};Time.now-s
 => 0.001428 
ruby-1.8.7-p302 :012 > s=Time.now;(1..10000).each{|_|Object.new};Time.now-s
 => 0.006603 

bundle exec ./script/console
rbx-1.2.3-20110315 :007 > s=Time.now;(1..10000).each{|_|};Time.now-s
 => 0.015319 
rbx-1.2.3-20110315 :015 > s=Time.now;(1..10000).each{|_|Object.new};Time.now-s
 => 0.016798 

MRI was consistent at about 0.006-0.007 seconds but Rubinius varied wildly between 0.007-0.018 (although more consistently at the high end of that). Both scale linearly as I tried 10000, 100000, and 1000000 and times multiplied by 10 each step.

The interesting thing here is that object construction was consistently quicker under Rubinius, and nearly always "negligible" in comparison to MRI.

What's really surprising is the following:

ruby -e 's=Time.now;(1..10000).each{|_|Object.new};puts Time.now-s'
0.006676

rbx -e 's=Time.now;(1..10000).each{|_|Object.new};puts Time.now-s'
0.0041519999999999994

Rubinius is consistently faster than MRI.

All of this lead me back to profile ActionController::Resources#resources which seems to do a lot with Array#each and Hash#[] (these are the highest after Rubinius::Tooling.disable in the profiler output):

  %   cumulative   self                self     total
 time   seconds   seconds      calls  ms/call  ms/call  name
------------------------------------------------------------
   6.61    0.27      0.08       2300     0.03     0.12  Array#each
   4.34    0.05      0.05       3919     0.01     0.01  Hash#[]

Full output in the 3rd file of this gist.

===== Thread 0 =====
Total running time: 96.534384102s
index % time self children called name
----------------------------------------------------------
[1] 84.6 0.00 81.69 1 Rubinius::Loader#script [1]
0.00 81.69 1 Rubinius::CodeLoader.load_script [2]
-------------------------------------------------------
0.00 81.69 1 Rubinius::Loader#script [1]
[2] 84.6 0.00 81.69 1 Rubinius::CodeLoader.load_script [2]
0.00 81.69 1 Rubinius::CodeLoader#load_script [3]
-------------------------------------------------------
0.00 81.69 1 Rubinius::CodeLoader.load_script [2]
[3] 84.6 0.00 81.69 1 Rubinius::CodeLoader#load_script [3]
0.00 81.68 1 Rubinius.run_script [4]
0.00 0.01 1 Rubinius::CodeLoader#load_file
-------------------------------------------------------
0.00 81.69 1 Rubinius::CodeLoader#load_script [3]
[4] 84.6 0.00 81.68 1 Rubinius.run_script [4]
0.00 81.68 1 script:/Users/matt/.rvm/gems/rbx-1.2.3-20110315@sequencescape/bin/cucumber [5]
-------------------------------------------------------
0.00 81.68 1 Rubinius.run_script [4]
[5] 84.6 0.00 81.68 1 script:/Users/matt/.rvm/gems/rbx-1.2.3-20110315@sequencescape/bin/cucumber [5]
0.00 81.68 1 Kernel#load [6]
0.00 0.00 1 Kernel#require
-------------------------------------------------------
0.00 81.68 1 script:/Users/matt/.rvm/gems/rbx-1.2.3-20110315@sequencescape/bin/cucumber [5]
[6] 84.6 0.00 81.68 1 Kernel#load [6]
0.00 81.68 1 Rubinius.run_script [7]
-------------------------------------------------------
0.00 81.68 1 Kernel#load [6]
[7] 84.6 0.00 81.68 1 Rubinius.run_script [7]
0.00 81.68 1 script:/Users/matt/.rvm/gems/rbx-1.2.3-20110315@sequencescape/gems/cucumber-0.10.2/bin/cucumber [8]
-------------------------------------------------------
0.00 81.68 1 Rubinius.run_script [7]
[8] 84.6 0.00 81.68 1 script:/Users/matt/.rvm/gems/rbx-1.2.3-20110315@sequencescape/gems/cucumber-0.10.2/bin/cucumber [8]
0.00 80.89 1 Cucumber::Cli::Main.execute [9]
0.00 0.79 2 Kernel#require
-------------------------------------------------------
0.00 81.68 1 script:/Users/matt/.rvm/gems/rbx-1.2.3-20110315@sequencescape/gems/cucumber-0.10.2/bin/cucumber [8]
[9] 83.8 0.00 80.89 1 Cucumber::Cli::Main.execute [9]
0.00 80.89 1 Cucumber::Cli::Main#execute! [10]
-------------------------------------------------------
0.00 80.89 1 Cucumber::Cli::Main.execute [9]
[10] 83.8 0.00 80.89 1 Cucumber::Cli::Main#execute! [10]
0.00 80.67 1 Cucumber::Runtime#run! [11]
0.00 0.13 1 Cucumber::Cli::Main#run_drb_client
0.00 0.08 1 Cucumber::Runtime#initialize
-------------------------------------------------------
0.00 80.89 1 Cucumber::Cli::Main#execute! [10]
[11] 83.6 0.00 80.67 1 Cucumber::Runtime#run! [11]
0.00 73.84 1 Cucumber::Runtime#load_step_definitions [12]
0.00 6.67 1 Cucumber::Ast::TreeWalker#visit_features
0.00 0.11 1 Cucumber::Runtime#features
0.00 0.04 1 Cucumber::Cli::Configuration#build_tree_walker
-------------------------------------------------------
0.00 80.67 1 Cucumber::Runtime#run! [11]
[12] 76.5 0.00 73.84 1 Cucumber::Runtime#load_step_definitions [12]
0.00 73.69 1 Cucumber::Runtime::SupportCode#load_files! [13]
0.00 0.07 1 Cucumber::Cli::Configuration#support_to_load
0.00 0.07 1 Cucumber::Cli::Configuration#step_defs_to_load
-------------------------------------------------------
0.00 73.84 1 Cucumber::Runtime#load_step_definitions [12]
[13] 76.3 0.00 73.69 1 Cucumber::Runtime::SupportCode#load_files! [13]
0.00 73.69 1 Array#each [14]
-------------------------------------------------------
0.00 73.69 1 Cucumber::Runtime::SupportCode#load_files! [13]
[14] 76.3 0.00 73.69 1 Array#each [14]
0.00 73.69 221 Cucumber::Runtime::SupportCode::load_files!<77> {} [15]
-------------------------------------------------------
0.00 73.69 1 Array#each [14]
[15] 76.3 0.00 73.69 221 Cucumber::Runtime::SupportCode::load_files!<77> {} [15]
0.00 73.69 221 Cucumber::Runtime::SupportCode#load_file [16]
-------------------------------------------------------
0.00 73.69 221 Cucumber::Runtime::SupportCode::load_files!<77> {} [15]
[16] 76.3 0.00 73.69 221 Cucumber::Runtime::SupportCode#load_file [16]
0.00 73.52 110 Cucumber::RbSupport::RbLanguage#load_code_file [17]
0.00 0.17 221 Cucumber::Runtime::SupportCode#programming_language_for
-------------------------------------------------------
0.00 73.69 221 Cucumber::Runtime::SupportCode#load_file [16]
[17] 76.2 0.00 73.52 110 Cucumber::RbSupport::RbLanguage#load_code_file [17]
0.00 71.98 1 Kernel#load [18]
0.00 1.52 109 ActiveSupport::Dependencies::Loadable#load
0.01 0.01 110 File.expand_path
-------------------------------------------------------
0.00 73.52 110 Cucumber::RbSupport::RbLanguage#load_code_file [17]
[18] 74.6 0.00 71.98 1 Kernel#load [18]
0.00 71.98 1 Rubinius.run_script [19]
-------------------------------------------------------
0.00 71.98 1 Kernel#load [18]
[19] 74.6 0.00 71.98 1 Rubinius.run_script [19]
0.00 71.98 1 script:/Users/matt/Projects/work/mattdenner/sequencescape/features/support/env.rb [20]
-------------------------------------------------------
0.00 71.98 1 Rubinius.run_script [19]
[20] 74.6 0.00 71.98 1 script:/Users/matt/Projects/work/mattdenner/sequencescape/features/support/env.rb [20]
0.00 69.13 2 Kernel#require [21]
0.00 2.74 11 ActiveSupport::Dependencies::Loadable#require
0.00 0.08 1 TruncateWithinReason#initialize
0.00 0.03 1 DatabaseCleaner.strategy=
-------------------------------------------------------
0.00 71.98 1 script:/Users/matt/Projects/work/mattdenner/sequencescape/features/support/env.rb [20]
[21] 71.6 0.00 69.13 2 Kernel#require [21]
0.00 69.13 2 Rubinius::CodeLoader.require [22]
-------------------------------------------------------
0.00 69.13 2 Kernel#require [21]
[22] 71.6 0.00 69.13 2 Rubinius::CodeLoader.require [22]
0.00 69.12 1 Rubinius.run_script [23]
0.00 0.00 2 Rubinius::CodeLoader#require
-------------------------------------------------------
0.00 69.13 2 Rubinius::CodeLoader.require [22]
[23] 71.6 0.00 69.12 1 Rubinius.run_script [23]
0.00 69.12 1 script:/Users/matt/Projects/work/mattdenner/sequencescape/config/environment.rb [24]
-------------------------------------------------------
0.00 69.12 1 Rubinius.run_script [23]
[24] 71.6 0.00 69.12 1 script:/Users/matt/Projects/work/mattdenner/sequencescape/config/environment.rb [24]
0.00 68.98 1 Rails::Initializer.run [25]
0.00 0.14 1 Kernel#require
-------------------------------------------------------
0.00 69.12 1 script:/Users/matt/Projects/work/mattdenner/sequencescape/config/environment.rb [24]
[25] 71.5 0.00 68.98 1 Rails::Initializer.run [25]
0.00 68.97 1 Rails::Initializer#process [26]
0.00 0.00 1 Rails::Configuration#initialize
0.00 0.00 1 Object::__script__<13> {}
-------------------------------------------------------
0.00 68.98 1 Rails::Initializer.run [25]
[26] 71.5 0.00 68.97 1 Rails::Initializer#process [26]
0.00 36.43 1 Rails::Initializer#initialize_routing [27]
0.00 8.25 1 Rails::Initializer#load_application_classes
0.00 8.06 1 Rails::Initializer#load_view_paths
0.00 5.32 1 Rails::Initializer#require_frameworks
0.00 2.22 2 Rails::Initializer#load_gems
0.00 2.03 1 Rails::Initializer#initialize_database
0.00 1.80 1 Rails::Initializer#initialize_framework_caches
0.00 1.43 2 Rails::Initializer#add_gem_load_paths
0.00 1.26 1 Rails::Initializer#initialize_metal
0.00 0.78 1 Rails::Initializer#initialize_time_zone
-------------------------------------------------------
0.00 68.97 1 Rails::Initializer#process [26]
[27] 37.7 0.00 36.43 1 Rails::Initializer#initialize_routing [27]
0.00 36.43 1 ActionController::Routing::RouteSet#reload! [28]
-------------------------------------------------------
0.00 36.43 1 Rails::Initializer#initialize_routing [27]
[28] 37.7 0.00 36.43 1 ActionController::Routing::RouteSet#reload! [28]
0.00 36.43 1 ActionController::Routing::RouteSet#load_routes! [29]
0.00 0.00 1 ActionController::Routing::RouteSet#clear!
-------------------------------------------------------
0.00 36.43 1 ActionController::Routing::RouteSet#reload! [28]
[29] 37.7 0.00 36.43 1 ActionController::Routing::RouteSet#load_routes! [29]
0.00 36.43 1 Array#each [30]
-------------------------------------------------------
0.00 36.43 1 ActionController::Routing::RouteSet#load_routes! [29]
[30] 37.7 0.00 36.43 1 Array#each [30]
0.00 36.43 1 ActionController::Routing::RouteSet::load_routes!<287> {} [31]
-------------------------------------------------------
0.00 36.43 1 Array#each [30]
[31] 37.7 0.00 36.43 1 ActionController::Routing::RouteSet::load_routes!<287> {} [31]
0.00 36.43 1 ActiveSupport::Dependencies::Loadable#load [32]
-------------------------------------------------------
0.00 36.43 1 ActionController::Routing::RouteSet::load_routes!<287> {} [31]
[32] 37.7 0.00 36.43 1 ActiveSupport::Dependencies::Loadable#load [32]
0.00 36.43 1 Kernel#load [33]
-------------------------------------------------------
0.00 36.43 1 ActiveSupport::Dependencies::Loadable#load [32]
[33] 37.7 0.00 36.43 1 Kernel#load [33]
0.00 36.42 1 Rubinius.run_script [34]
0.00 0.00 1 Rubinius::CodeLoader#load
-------------------------------------------------------
0.00 36.43 1 Kernel#load [33]
[34] 37.7 0.00 36.42 1 Rubinius.run_script [34]
0.00 36.42 1 script:/Users/matt/Projects/work/mattdenner/sequencescape/config/routes.rb [35]
-------------------------------------------------------
0.00 36.42 1 Rubinius.run_script [34]
[35] 37.7 0.00 36.42 1 script:/Users/matt/Projects/work/mattdenner/sequencescape/config/routes.rb [35]
0.00 36.42 1 ActionController::Routing::RouteSet#draw [36]
-------------------------------------------------------
0.00 36.42 1 script:/Users/matt/Projects/work/mattdenner/sequencescape/config/routes.rb [35]
[36] 37.7 0.00 36.42 1 ActionController::Routing::RouteSet#draw [36]
0.00 36.34 1 Object::__script__<1> {} [37]
0.00 0.08 1 ActionController::Routing::RouteSet#install_helpers
-------------------------------------------------------
0.00 36.42 1 ActionController::Routing::RouteSet#draw [36]
[37] 37.7 0.00 36.34 1 Object::__script__<1> {} [37]
0.00 28.34 55 ActionController::Resources#resources [38]
0.00 6.17 5 Object#with_options
0.00 1.38 20 ActionController::Routing::RouteSet::Mapper#pass_qc_state
0.00 0.33 29 ActionController::Routing::RouteSet::Mapper#connect
0.00 0.07 1 ActionController::Resources#resource
0.00 0.04 1 ActionController::Routing::RouteSet::Mapper#root
0.00 0.00 297 Hash#[]=
0.00 0.00 126 Hash.new_from_literal
-------------------------------------------------------
0.00 36.34 1 Object::__script__<1> {} [37]
[38] 29.4 0.00 28.34 55 ActionController::Resources#resources [38]
0.00 28.34 55 Array#each [39]
-------------------------------------------------------
0.00 28.34 55 ActionController::Resources#resources [38]
[39] 29.4 0.00 28.34 55 Array#each [39]
0.00 28.34 55 ActionController::Resources::resources<447> {} [40]
-------------------------------------------------------
0.00 28.34 55 Array#each [39]
[40] 29.4 0.00 28.34 55 ActionController::Resources::resources<447> {} [40]
0.00 28.34 55 ActionController::Resources#map_resource [41]
0.00 0.00 55 Kernel#dup
-------------------------------------------------------
0.00 28.34 55 ActionController::Resources::resources<447> {} [40]
[41] 29.4 0.00 28.34 55 ActionController::Resources#map_resource [41]
0.00 28.26 55 Object#with_options [42]
0.00 0.07 55 ActionController::Resources::Resource#initialize
-------------------------------------------------------
0.00 28.34 55 ActionController::Resources#map_resource [41]
[42] 29.3 0.00 28.26 55 Object#with_options [42]
0.00 28.25 55 ActionController::Resources::map_resource<528> {} [43]
0.00 0.01 1 Autoload#call
-------------------------------------------------------
0.00 28.26 55 Object#with_options [42]
[43] 29.3 0.00 28.25 55 ActionController::Resources::map_resource<528> {} [43]
0.00 8.39 10 Object#with_options
0.00 7.51 55 ActionController::Resources#map_member_actions
0.00 4.09 55 ActionController::Resources#map_default_collection_actions
0.00 3.30 55 ActionController::Resources#map_new_actions
0.00 3.04 55 ActionController::Resources#map_collection_actions
0.00 1.92 55 ActionController::Resources#map_associations
-------------------------------------------------------
[44] 14.2 0.00 13.69 1 Rubinius::Loader#requires [44]
0.00 13.69 1 Array#each [45]
-------------------------------------------------------
0.00 13.69 1 Rubinius::Loader#requires [44]
[45] 14.2 0.00 13.69 1 Array#each [45]
0.00 13.69 1 Rubinius::Loader::requires<571> {}
-------------------------------------------------------
110,699 methods omitted
110,744 methods called a total of 0 times
===== Thread 2 =====
Total running time: 96.534384102s
index % time self children called name
----------------------------------------------------------
[1] 17.3 0.00 16.67 1 Thread#__run__ [1]
0.00 16.67 1 HTTPClient::TimeoutScheduler::start_timer_thread<88> {} [2]
-------------------------------------------------------
0.00 16.67 1 Thread#__run__ [1]
[2] 17.3 0.00 16.67 1 HTTPClient::TimeoutScheduler::start_timer_thread<88> {} [2]
0.00 16.67 1 Kernel#sleep [3]
-------------------------------------------------------
0.00 16.67 1 HTTPClient::TimeoutScheduler::start_timer_thread<88> {} [2]
[3] 17.3 0.00 16.67 1 Kernel#sleep [3]
16.67 0.00 1 Rubinius::Channel#receive_timeout [4]
-------------------------------------------------------
0.00 16.67 1 Kernel#sleep [3]
[4] 17.3 16.67 0.00 1 Rubinius::Channel#receive_timeout [4]
-------------------------------------------------------
4 methods called a total of 0 times
resources([:reference_genomes])
Thread 0: total running time: 0.749285402s
% cumulative self self total
time seconds seconds calls ms/call ms/call name
------------------------------------------------------------
40.61 0.47 0.47 1 474.91 474.91 Rubinius::Tooling.disable
6.61 0.27 0.08 2300 0.03 0.12 Array#each
4.34 0.05 0.05 3919 0.01 0.01 Hash#[]
3.44 0.04 0.04 263 0.15 0.16 Rubinius::AST::SendWithArguments#bytecode
2.99 0.09 0.03 99 0.35 0.90 Rubinius::AST::If#bytecode
2.93 0.04 0.03 192 0.18 0.22 Rubinius::AST::And#bytecode
2.83 0.03 0.03 4028 0.01 0.01 Hash#find_entry
2.43 0.03 0.03 6935 0.00 0.01 Rubinius::Melbourne::process_transforms<89> {}
2.31 0.06 0.03 30 0.90 2.15 Rubinius::Melbourne#string_to_ast
1.92 0.02 0.02 349 0.06 0.05 Rubinius::AST::Send#bytecode
1.62 0.02 0.02 347 0.05 0.05 Rubinius::AST::ActualArguments#bytecode
1.59 0.02 0.02 381 0.05 0.04 Rubinius::AST::ActualArguments::bytecode<355> {}
1.24 0.02 0.01 99 0.15 0.18 Rubinius::AST::Not#bytecode
1.17 0.10 0.01 230 0.06 0.46 Rubinius::AST::Block::bytecode<88> {}
1.11 0.04 0.01 146 0.09 0.29 Rubinius::AST::LocalVariableAssignment#bytecode
0.89 0.01 0.01 77 0.14 0.18 Rubinius::Generator#encode
0.88 0.04 0.01 713 0.01 0.06 Rubinius::Melbourne#process_transforms
0.87 0.21 0.01 30 0.34 6.88 Rubinius::Compiler.compile_eval
0.75 0.01 0.01 2 4.38 4.38 GC.collect_young
0.75 0.11 0.01 38 0.23 2.77 Rubinius::AST::Define#compile_body
0.75 0.04 0.01 567 0.02 0.07 Rubinius::Melbourne#process_call
0.70 0.01 0.01 77 0.11 0.17 Rubinius::Generator::BasicBlock#validate_stack
0.69 0.13 0.01 120 0.07 1.09 Rubinius::Compiler::Stage#run_next
0.68 0.10 0.01 7 1.13 14.70 ActionController::Routing::RouteBuilder#build
0.64 0.01 0.01 1466 0.01 0.01 Rubinius::Generator::BasicBlock#flow_stack_size
0.62 0.13 0.01 30 0.24 4.35 Rubinius::Compiler::Generator#run
0.58 0.02 0.01 30 0.23 0.52 Rubinius::Compiler::Encoder#run
0.56 0.01 0.01 161 0.04 0.07 Thread.detect_recursion
0.51 0.01 0.01 36 0.17 0.17 Rubinius::AST::Send#defined
0.46 0.01 0.01 159 0.03 0.04 Array#collect
0.45 0.01 0.01 8 0.66 0.66 Rubinius::AST::Iter#bytecode
0.44 0.05 0.01 7 0.74 7.77 ActionController::Routing::Route#write_generation!
0.44 0.11 0.01 38 0.13 2.91 Rubinius::AST::Define#bytecode
0.43 0.01 0.01 46 0.11 0.29 Rubinius::Generator::encode<246> {}
0.43 0.01 0.01 713 0.01 0.01 Rubinius::AST::SendFastMath.match?
0.40 0.01 0.00 47 0.10 0.24 Rubinius::AST::ToString#bytecode
0.39 0.00 0.00 16 0.28 0.28 ActionController::Routing::Optimisation::Optimiser#source_code
0.38 0.01 0.00 648 0.01 0.01 Rubinius::AST::SendInstructionMethod.match?
0.37 0.11 0.00 106 0.04 0.99 Enumerable#each_with_index
0.37 0.11 0.00 273 0.02 0.38 Enumerable::each_with_index<448> {}
0.36 0.11 0.00 84 0.05 1.25 Rubinius::AST::Block#bytecode
0.34 0.07 0.00 30 0.13 2.17 Rubinius::Melbourne#parse_string
0.33 0.00 0.00 33 0.12 0.12 ActionController::Routing::RouteBuilder#segment_for
0.32 0.01 0.00 23 0.16 0.55 Rubinius::AST::DynamicString#bytecode
0.30 0.03 0.00 7 0.50 4.78 ActionController::Routing::Route#write_recognition!
90 methods omitted
135 methods called a total of 27,805 times
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment