Skip to content

Instantly share code, notes, and snippets.

@pglombardo

pglombardo/1.8.7-p374.txt

Last active May 16, 2022 12:36
Show Gist options
  • Save pglombardo/5978849 to your computer and use it in GitHub Desktop.
Save pglombardo/5978849 to your computer and use it in GitHub Desktop.
Download ZIP
Kernel.caller Performance Across Different Ruby Versions
Raw
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
Raw
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
Raw
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
Raw
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, {})
Raw
Gemfile
source "http://rubygems.org"
gem 'ruby-prof'
Raw
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
@ogirginc
Copy link

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