Kernel.caller Performance Across Different Ruby Versions

1.8.7-p374.txt

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

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

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

application.rb

#!/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, {})

Gemfile

source "http://rubygems.org"

gem 'ruby-prof'

summary.txt

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

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.