public
Last active

Kernel.caller Performance Across Different Ruby Versions

  • Download Gist
1.8.7-p374.txt
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72
Backtrace generated 500 times with 1508 frames
Thread ID: 69872793616820
Total Time: 0.377622164
Sort by: total_time
 
%total %self total self wait child calls Name
--------------------------------------------------------------------------------
100.00% 0.01% 0.378 0.000 0.000 0.378 1 Global#[No method]
0.378 0.000 0.000 0.378 1/301 Object#one
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 300/301 Object#five
0.378 0.000 0.000 0.378 1/301 Global#[No method]
99.99% 0.00% 0.378 0.000 0.000 0.378 301 *Object#one
0.378 0.000 0.000 0.378 301/301 Object#two
0.000 0.000 0.000 0.000 301/1204 Fixnum#+
--------------------------------------------------------------------------------
0.378 0.000 0.000 0.378 301/301 Object#one
99.99% 0.00% 0.378 0.000 0.000 0.378 301 *Object#two
0.378 0.000 0.000 0.378 301/301 Object#three
0.000 0.000 0.000 0.000 301/1204 Fixnum#+
--------------------------------------------------------------------------------
0.378 0.000 0.000 0.378 301/301 Object#two
99.99% 0.00% 0.378 0.000 0.000 0.378 301 *Object#three
0.378 0.000 0.000 0.378 301/301 Object#four
0.000 0.000 0.000 0.000 301/1204 Fixnum#+
--------------------------------------------------------------------------------
0.378 0.000 0.000 0.378 301/301 Object#three
99.99% 0.00% 0.378 0.000 0.000 0.378 301 *Object#four
0.378 0.000 0.000 0.378 301/301 Object#five
0.000 0.000 0.000 0.000 301/1204 Fixnum#+
--------------------------------------------------------------------------------
0.378 0.000 0.000 0.378 301/301 Object#four
99.99% 0.00% 0.378 0.000 0.000 0.378 301 *Object#five
0.369 0.001 0.000 0.369 1/1 Integer#times
0.001 0.001 0.000 0.000 1/500 <Module::Kernel>#caller
0.000 0.000 0.000 0.000 301/301 Fixnum#>
0.000 0.000 0.000 0.000 1/1 Kernel#puts
0.000 0.000 0.000 0.000 1/1 Array#count
0.000 0.000 0.000 0.000 1/1 Fixnum#to_s
0.000 0.000 0.000 0.000 300/301 Object#one
--------------------------------------------------------------------------------
0.369 0.001 0.000 0.369 1/1 Object#five
97.81% 0.22% 0.369 0.001 0.000 0.369 1 Integer#times
0.369 0.369 0.000 0.000 499/500 <Module::Kernel>#caller
--------------------------------------------------------------------------------
0.001 0.001 0.000 0.000 1/500 Object#five
0.369 0.369 0.000 0.000 499/500 Integer#times
97.74% 97.74% 0.369 0.369 0.000 0.000 500 <Module::Kernel>#caller
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 301/1204 Object#two
0.000 0.000 0.000 0.000 301/1204 Object#three
0.000 0.000 0.000 0.000 301/1204 Object#four
0.000 0.000 0.000 0.000 301/1204 Object#one
0.38% 0.38% 0.001 0.001 0.000 0.000 1204 Fixnum#+
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 301/301 Object#five
0.09% 0.09% 0.000 0.000 0.000 0.000 301 Fixnum#>
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Object#five
0.01% 0.00% 0.000 0.000 0.000 0.000 1 Kernel#puts
0.000 0.000 0.000 0.000 2/2 IO#write
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 2/2 Kernel#puts
0.01% 0.01% 0.000 0.000 0.000 0.000 2 IO#write
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Object#five
0.00% 0.00% 0.000 0.000 0.000 0.000 1 Array#count
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Object#five
0.00% 0.00% 0.000 0.000 0.000 0.000 1 Fixnum#to_s
 
* indicates recursively called methods
1.9.3p448.txt
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63
Backtrace generated 500 times with 1508 frames
Thread ID: 10053620
Fiber ID: 10898140
Total Time: 0.46813809900000003
Sort by: total_time
 
%total %self total self wait child calls Name
--------------------------------------------------------------------------------
100.00% 0.01% 0.468 0.000 0.000 0.468 1 Global#[No method]
0.468 0.000 0.000 0.468 1/301 Object#one
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 300/301 Object#five
0.468 0.000 0.000 0.468 1/301 Global#[No method]
99.99% 0.00% 0.468 0.000 0.000 0.468 301 *Object#one
0.468 0.000 0.000 0.468 301/301 Object#two
--------------------------------------------------------------------------------
0.468 0.000 0.000 0.468 301/301 Object#one
99.99% 0.00% 0.468 0.000 0.000 0.468 301 *Object#two
0.468 0.000 0.000 0.468 301/301 Object#three
--------------------------------------------------------------------------------
0.468 0.000 0.000 0.468 301/301 Object#two
99.99% 0.00% 0.468 0.000 0.000 0.468 301 *Object#three
0.468 0.000 0.000 0.468 301/301 Object#four
--------------------------------------------------------------------------------
0.468 0.000 0.000 0.468 301/301 Object#three
99.99% 0.00% 0.468 0.000 0.000 0.468 301 *Object#four
0.468 0.000 0.000 0.468 301/301 Object#five
--------------------------------------------------------------------------------
0.468 0.000 0.000 0.468 301/301 Object#four
99.99% 0.00% 0.468 0.000 0.000 0.468 301 *Object#five
0.463 0.001 0.000 0.462 1/1 Integer#times
0.001 0.001 0.000 0.000 1/500 <Module::Kernel>#caller
0.000 0.000 0.000 0.000 1/1 Kernel#puts
0.000 0.000 0.000 0.000 1/1 Fixnum#to_s
0.000 0.000 0.000 0.000 1/1 Array#count
0.000 0.000 0.000 0.000 300/301 Object#one
--------------------------------------------------------------------------------
0.463 0.001 0.000 0.462 1/1 Object#five
98.83% 0.22% 0.463 0.001 0.000 0.462 1 Integer#times
0.462 0.462 0.000 0.000 499/500 <Module::Kernel>#caller
--------------------------------------------------------------------------------
0.001 0.001 0.000 0.000 1/500 Object#five
0.462 0.462 0.000 0.000 499/500 Integer#times
98.74% 98.74% 0.462 0.462 0.000 0.000 500 <Module::Kernel>#caller
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Object#five
0.01% 0.00% 0.000 0.000 0.000 0.000 1 Kernel#puts
0.000 0.000 0.000 0.000 1/1 IO#puts
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Kernel#puts
0.01% 0.00% 0.000 0.000 0.000 0.000 1 IO#puts
0.000 0.000 0.000 0.000 2/2 IO#write
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 2/2 IO#puts
0.01% 0.01% 0.000 0.000 0.000 0.000 2 IO#write
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Object#five
0.00% 0.00% 0.000 0.000 0.000 0.000 1 Fixnum#to_s
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Object#five
0.00% 0.00% 0.000 0.000 0.000 0.000 1 Array#count
 
* indicates recursively called methods
2.0.0-p247.txt
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63
Backtrace generated 500 times with 1508 frames
Thread ID: 69971812621940
Fiber ID: 69971813688700
Total Time: 0.776138452
Sort by: total_time
 
%total %self total self wait child calls Name
--------------------------------------------------------------------------------
100.00% 0.00% 0.776 0.000 0.000 0.776 1 Global#[No method]
0.776 0.000 0.000 0.776 1/301 Object#one
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 300/301 Object#five
0.776 0.000 0.000 0.776 1/301 Global#[No method]
100.00% 0.00% 0.776 0.000 0.000 0.776 301 *Object#one
0.776 0.000 0.000 0.776 301/301 Object#two
--------------------------------------------------------------------------------
0.776 0.000 0.000 0.776 301/301 Object#one
99.99% 0.00% 0.776 0.000 0.000 0.776 301 *Object#two
0.776 0.000 0.000 0.776 301/301 Object#three
--------------------------------------------------------------------------------
0.776 0.000 0.000 0.776 301/301 Object#two
99.99% 0.00% 0.776 0.000 0.000 0.776 301 *Object#three
0.776 0.000 0.000 0.776 301/301 Object#four
--------------------------------------------------------------------------------
0.776 0.000 0.000 0.776 301/301 Object#three
99.99% 0.00% 0.776 0.000 0.000 0.776 301 *Object#four
0.776 0.000 0.000 0.776 301/301 Object#five
--------------------------------------------------------------------------------
0.776 0.000 0.000 0.776 301/301 Object#four
99.99% 0.00% 0.776 0.000 0.000 0.776 301 *Object#five
0.770 0.002 0.000 0.768 1/1 Integer#times
0.001 0.001 0.000 0.000 1/500 <Module::Kernel>#caller
0.000 0.000 0.000 0.000 1/1 Kernel#puts
0.000 0.000 0.000 0.000 1/1 Fixnum#to_s
0.000 0.000 0.000 0.000 1/1 Array#count
0.000 0.000 0.000 0.000 300/301 Object#one
--------------------------------------------------------------------------------
0.770 0.002 0.000 0.768 1/1 Object#five
99.24% 0.28% 0.770 0.002 0.000 0.768 1 Integer#times
0.768 0.768 0.000 0.000 499/500 <Module::Kernel>#caller
--------------------------------------------------------------------------------
0.001 0.001 0.000 0.000 1/500 Object#five
0.768 0.768 0.000 0.000 499/500 Integer#times
99.11% 99.11% 0.769 0.769 0.000 0.000 500 <Module::Kernel>#caller
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Object#five
0.01% 0.00% 0.000 0.000 0.000 0.000 1 Kernel#puts
0.000 0.000 0.000 0.000 1/1 IO#puts
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Kernel#puts
0.01% 0.00% 0.000 0.000 0.000 0.000 1 IO#puts
0.000 0.000 0.000 0.000 2/2 IO#write
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 2/2 IO#puts
0.01% 0.01% 0.000 0.000 0.000 0.000 2 IO#write
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Object#five
0.00% 0.00% 0.000 0.000 0.000 0.000 1 Fixnum#to_s
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Object#five
0.00% 0.00% 0.000 0.000 0.000 0.000 1 Array#count
 
* indicates recursively called methods
Gemfile
Ruby
1 2 3
source "http://rubygems.org"
 
gem 'ruby-prof'
application.rb
Ruby
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43
#!/usr/bin/env ruby
 
require 'ruby-prof'
 
def one(x = 0)
x = x + 1
two(x)
end
 
def two(x = 0)
x = x + 1
three(x)
end
 
def three(x = 0)
x = x + 1
four(x)
end
 
def four(x = 0)
x = x + 1
five(x)
end
 
def five(x = 0)
if x > 1200
499.times do |x|
bt = Kernel.caller
end
bt = Kernel.caller
puts "Backtrace generated 500 times with #{bt.count} frames"
else
one(x)
end
end
 
result = RubyProf.profile do
one
end
 
# Print a graph profile to text
printer = RubyProf::GraphPrinter.new(result)
printer.print(STDOUT, {})
summary.txt
1 2 3 4
Kernel.caller Total Times across Ruby Versions
Ruby 1.8.7-p374: 0.369
Ruby 1.9.3p448 : 0.462
Ruby 2.0.0-p247: 0.769

Please sign in to comment on this gist.

Something went wrong with that request. Please try again.