Skip to content

Instantly share code, notes, and snippets.

Embed
What would you like to do?
Kernel.caller Performance Across Different Ruby Versions
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
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
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
#!/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, {})
source "http://rubygems.org"
gem 'ruby-prof'
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
@ogirginc
Copy link

ogirginc commented May 16, 2022

For ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [arm64-darwin21], total time is 0.246783510025125.

Output
Backtrace generated 500 times with 1508 frames
Measure Mode: wall_time
Thread ID: 80
Fiber ID: 60
Total Time: 0.246783510025125
Sort by: total_time

  %total   %self      total       self       wait      child            calls     name                          location
------------------------------------------------------------------------------------------------------------------------------------------------------
 100.00%   0.00%      0.247      0.000      0.000      0.247                1     [global]#                      application.rb:38
                      0.247      0.000      0.000      0.247            1/301     Object#one
------------------------------------------------------------------------------------------------------------------------------------------------------
                      0.247      0.000      0.000      0.247            1/301     [global]#
                     73.903      0.000      0.000     73.903          300/301     Object#five
 100.00%   0.05%      0.247      0.000      0.000      0.247              301    *Object#one                     application.rb:5
                     74.150      0.000      0.000     74.150          301/301     Object#two
                      0.000      0.000      0.000      0.000         301/1204     Integer#+
------------------------------------------------------------------------------------------------------------------------------------------------------
                     74.150      0.000      0.000     74.150          301/301     Object#one
 100.00%   0.06%      0.247      0.000      0.000      0.247              301    *Object#two                     application.rb:10
                     74.150      0.000      0.000     74.150          301/301     Object#three
                      0.000      0.000      0.000      0.000         301/1204     Integer#+
------------------------------------------------------------------------------------------------------------------------------------------------------
                     74.150      0.000      0.000     74.150          301/301     Object#two
 100.00%   0.05%      0.247      0.000      0.000      0.247              301    *Object#three                   application.rb:15
                     74.150      0.000      0.000     74.149          301/301     Object#four
                      0.000      0.000      0.000      0.000         301/1204     Integer#+
------------------------------------------------------------------------------------------------------------------------------------------------------
                     74.150      0.000      0.000     74.149          301/301     Object#three
 100.00%   0.05%      0.247      0.000      0.000      0.247              301    *Object#four                    application.rb:20
                     74.149      0.000      0.000     74.149          301/301     Object#five
                      0.000      0.000      0.000      0.000         301/1204     Integer#+
------------------------------------------------------------------------------------------------------------------------------------------------------
                     74.149      0.000      0.000     74.149          301/301     Object#four
 100.00%   0.05%      0.247      0.000      0.000      0.247              301    *Object#five                    application.rb:25
                     73.903      0.000      0.000     73.903          300/301     Object#one
                      0.245      0.000      0.000      0.245              1/1     Integer#times
                      0.000      0.000      0.000      0.000            1/500     <Module::Kernel>#caller
                      0.000      0.000      0.000      0.000          301/301     Integer#>
                      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/500     Object#five
                      0.245      0.245      0.000      0.000          499/500     Integer#times
  99.60%  99.60%      0.246      0.246      0.000      0.000              500     <Module::Kernel>#caller
------------------------------------------------------------------------------------------------------------------------------------------------------
                      0.245      0.000      0.000      0.245              1/1     Object#five
  99.46%   0.04%      0.245      0.000      0.000      0.245                1     Integer#times
                      0.245      0.245      0.000      0.000          499/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#one
                      0.000      0.000      0.000      0.000         301/1204     Object#four
   0.08%   0.08%      0.000      0.000      0.000      0.000             1204     Integer#+
------------------------------------------------------------------------------------------------------------------------------------------------------
                      0.000      0.000      0.000      0.000          301/301     Object#five
   0.02%   0.02%      0.000      0.000      0.000      0.000              301     Integer#>
------------------------------------------------------------------------------------------------------------------------------------------------------
                      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              1/1     IO#write
------------------------------------------------------------------------------------------------------------------------------------------------------
                      0.000      0.000      0.000      0.000              1/1     IO#puts
   0.00%   0.00%      0.000      0.000      0.000      0.000                1     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

* recursively called methods

Columns are:

  %self     - The percentage of time spent in this method, derived from self_time/total_time.
  total     - The time spent in this method and its children.
  self      - The time spent in this method.
  wait      - The amount of time this method waited for other threads.
  child     - The time spent in this method's children.
  calls     - The number of times this method was called.
  name      - The name of the method.
  location  - The location of the method.

The interpretation of method names is:

  * MyObject#test - An instance method "test" of the class "MyObject"
  * <Object:MyObject>#test - The <> characters indicate a method on a singleton class.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment