Skip to content

Instantly share code, notes, and snippets.

@pglombardo

pglombardo/measure.md

Last active February 23, 2024 00:02
Show Gist options
  • Save pglombardo/676d887881c4e6295388 to your computer and use it in GitHub Desktop.
Save pglombardo/676d887881c4e6295388 to your computer and use it in GitHub Desktop.
Download ZIP
Comprehensive Guide to Ruby Performance Benchmarking
Raw
measure.md

GC.disable

Wall Clock Time versus CPU Time

An important difference to note is the how time is reported by various measurement methods. Wall clock time is the actual time passed in terms of human perception whereas CPU time is the time spent processing the work. CPU time doesn't include any delays waiting on resources to free up such as thread interrupts or garbage collection.

The Work to Measure

To keep things simple, we'll create a Ruby Proc and just repeatedly call that Proc for each of the measurement methods below.

work_proc = Proc.new {
  big = []

  1000.times do
    big << rand(36**16).to_s(36)
  end
  
  x = big.sort
  x.first
}

To give an idea of what this array will look like, this will print out the first five elements:

puts big[0..4]
=> ["nuwc05c4xuz1ua2l", "rpwgr1tpbmnnrp2q", "okco1ablpme8mguo", "hut9e5f2umzj2f5j", "ppqu554al4zcdwtm"]

General Ruby Tools

Time

start = Time.now
work_proc.call
finish = Time.now

# Result
total_time = finish - start
puts total_time

This will output a number (in seconds) similar to the following:

0.025681

Benchmark

require 'benchmark'
puts Benchmark.measure { work_proc.call }

http://www.ruby-doc.org/stdlib-1.9.3/libdoc/benchmark/rdoc/Benchmark.html

Linking to the older 1.9.3 Benchmark documentation because it has a good discussion about realtime in the comments section. Here's the 2.1.0 version if you need it.

Ruby-prof

gem install ruby-prof

require 'ruby-prof'

result = RubyProf.profile do
  work_proc.call
end

# Print a graph profile to text
printer = RubyProf::GraphPrinter.new(result)
printer.print(STDOUT, {})

This will output something along the lines of the following:

Thread ID: 70238909684700
Fiber ID: 70238917178180
Total Time: 0.007679000000000102
Sort by: total_time

  %total   %self      total       self       wait      child            calls    Name
--------------------------------------------------------------------------------
 100.00%   0.31%      0.008      0.000      0.000      0.008                1      <Object::Object>#__pry__
                      0.008      0.000      0.000      0.008              1/1      Proc#call
--------------------------------------------------------------------------------
                      0.008      0.000      0.000      0.008              1/1      <Object::Object>#__pry__
  99.69%   0.16%      0.008      0.000      0.000      0.008                1      Proc#call
                      0.007      0.003      0.000      0.005              1/1      Integer#times
                      0.000      0.000      0.000      0.000              1/1      Array#sort
                      0.000      0.000      0.000      0.000              1/1      Array#first
--------------------------------------------------------------------------------
                      0.007      0.003      0.000      0.005              1/1      Proc#call
  96.02%  34.00%      0.007      0.003      0.000      0.005                1      Integer#times
                      0.002      0.002      0.000      0.001        1000/1000      Kernel#rand
                      0.001      0.001      0.000      0.000        1000/1000      Bignum#to_s
                      0.001      0.001      0.000      0.000        1000/1000      Fixnum#**
--------------------------------------------------------------------------------
                      0.002      0.002      0.000      0.001        1000/1000      Integer#times
  31.98%  23.96%      0.002      0.002      0.000      0.001             1000      Kernel#rand
                      0.001      0.001      0.000      0.000        1000/1000      Kernel#respond_to_missing?
--------------------------------------------------------------------------------
                      0.001      0.001      0.000      0.000        1000/1000      Integer#times
  17.27%  17.27%      0.001      0.001      0.000      0.000             1000      Bignum#to_s
--------------------------------------------------------------------------------
                      0.001      0.001      0.000      0.000        1000/1000      Integer#times
  12.76%  12.76%      0.001      0.001      0.000      0.000             1000      Fixnum#**
--------------------------------------------------------------------------------
                      0.001      0.001      0.000      0.000        1000/1000      Kernel#rand
   8.02%   8.02%      0.001      0.001      0.000      0.000             1000      Kernel#respond_to_missing?
--------------------------------------------------------------------------------
                      0.000      0.000      0.000      0.000              1/1      Proc#call
   3.46%   3.46%      0.000      0.000      0.000      0.000                1      Array#sort
--------------------------------------------------------------------------------
                      0.000      0.000      0.000      0.000              1/1      Proc#call
   0.05%   0.05%      0.000      0.000      0.000      0.000                1      Array#first

* indicates recursively called methods

DTrace

TracePoint

Others:

Ruby on Rails Specific

Sinatra Specific

JRuby

Related Articles:

Test Framework Specific

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