profiling Array#push and Array#<< using ruby-prof gem and profiler in standard lib

array_prof.rb

#!/usr/bin/env ruby
# profiling Array#push and Array#<< using ruby-prof gem

# BUG: why does "Array#<<" not show-up on the profiler but "Array#push" does

begin
  require "ruby-prof"
rescue LoadError
  require "rubygems"
  require "ruby-prof"
end

def arr_push
  arr = []
  100.times { arr.push 'foobar' }
  arr.join(':')
end

def arr_push_operator
  arr = []
  100.times { arr << 'foobar' }
  arr.join(':')
end

printer_class = RubyProf::FlatPrinter
RubyProf.measure_mode = RubyProf::WALL_TIME

RubyProf.start
arr_push
results_push = RubyProf.stop

RubyProf.start
arr_push_operator
results_operator = RubyProf.stop

printer_push = printer_class.new(results_push)
printer_push.print($stderr)

$stderr.puts
$stderr.puts('-' * 100)
$stderr.puts

printer_operator = printer_class.new(results_operator)
printer_operator.print($stderr)

__END__

$ ruby -vw array_prof.rb 
ruby 1.9.2p0 (2010-08-18 revision 29036) [x86_64-linux]
Thread ID: 14423240
Total: 0.000441

 %self     total     self     wait    child    calls  name
 58.96      0.00     0.00     0.00     0.00        1  Integer#times
 29.93      0.00     0.00     0.00     0.00      100  Array#push
  4.31      0.00     0.00     0.00     0.00        1  Array#join
  4.31      0.00     0.00     0.00     0.00        1  Global#[No method]
  2.49      0.00     0.00     0.00     0.00        1  Object#arr_push



----------------------------------------------------------------------------------------------------

Thread ID: 14423240
Total: 0.000181

 %self     total     self     wait    child    calls  name
 79.01      0.00     0.00     0.00     0.00        1  Integer#times
 11.05      0.00     0.00     0.00     0.00        1  Array#join
  5.52      0.00     0.00     0.00     0.00        1  Global#[No method]
  4.42      0.00     0.00     0.00     0.00        1  Object#arr_push_operator

array_std_prof.rb

#!/usr/bin/env ruby
# profiling Array#push and Array#<< using profiler in standard lib

# BUG: why does "Array#<<" not show-up on the profiler but "Array#push" does. JRuby handles this correctly 
require 'profiler'

def arr_push
  arr = []
  100.times { arr.push 'foobar' }
  arr.join(':')
end

def arr_push_operator
  arr = []
  100.times { arr << 'foobar' }
  arr.join(':')
end

Profiler__.start_profile
arr_push
Profiler__.stop_profile
Profiler__.print_profile($stderr)

$stderr.puts
$stderr.puts('-' * 100)
$stderr.puts

Profiler__.start_profile
arr_push_operator
Profiler__.stop_profile
Profiler__.print_profile($stderr)

__END__

$ ruby -vw array_std_prof.rb 
ruby 1.9.2p0 (2010-08-18 revision 29036) [x86_64-linux]
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
  0.00     0.00      0.00      100     0.00     0.00  Array#push
  0.00     0.00      0.00        1     0.00     0.00  Integer#times
  0.00     0.00      0.00        1     0.00     0.00  Array#join
  0.00     0.00      0.00        1     0.00     0.00  Object#arr_push
  0.00     0.01      0.00        1     0.00    10.00  #toplevel

----------------------------------------------------------------------------------------------------

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
  0.00     0.00      0.00        1     0.00     0.00  Integer#times
  0.00     0.00      0.00        1     0.00     0.00  Array#join
  0.00     0.00      0.00        1     0.00     0.00  Object#arr_push_operator
  0.00     0.01      0.00        1     0.00    10.00  #toplevel

$ ruby -vw --debug array_std_prof.rb 
jruby 1.5.2 (ruby 1.8.7 patchlevel 249) (2010-08-20 1c5e29d) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_22) [amd64-java]
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 57.50     0.05      0.05        1    46.00    70.00  Integer#times
 30.00     0.07      0.02      100     0.24     0.24  Array#push
  3.75     0.07      0.00        1     3.00    74.00  Object#arr_push
  1.25     0.07      0.00        1     1.00     1.00  Array#join
  0.00     0.08      0.00        1     0.00    80.00  #toplevel

----------------------------------------------------------------------------------------------------

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 65.52     0.04      0.04        1    38.00    55.00  Integer#times
 29.31     0.06      0.02      100     0.17     0.17  Array#<<
  5.17     0.06      0.00        1     3.00    58.00  Object#arr_push_operator
  0.00     0.06      0.00        1     0.00     0.00  Array#join
  0.00     0.06      0.00        1     0.00    58.00  #toplevel