TracePoint, benchmark and profilers
Benchmark.measure
Before a profiler, a stopwatch. Benchmark.measure runs a block and prints the user time, the system time, the total and the real elapsed time:
ruby -r benchmark -e 'puts Benchmark.measure { 1_000_000.times { |i| i * 2 } }'
0.082450 0.000111 0.082561 ( 0.082567)
The last column in parentheses is wall-clock time; the first is the CPU the process used. On a quiet machine they are close. The numbers move between runs, so compare two versions of the same code in the same session rather than remembering an absolute value.
Benchmark.bm prints a table for several blocks, which is the quick way to compare an implementation with its replacement:
require "benchmark"
Benchmark.bm(10) do |x|
x.report("map") { (1..100_000).map { _1 * 2 } }
x.report("lazy") { (1..100_000).lazy.map { _1 * 2 }.to_a }
end
ruby -r benchmark -e 'Benchmark.bm(10) do |x|; x.report("map") { (1..100_000).map { _1 * 2 } }; x.report("lazy") { (1..100_000).lazy.map { _1 * 2 }.to_a }; end'
user system total real map 0.014728 0.000928 0.015656 ( 0.015659) lazy 0.059696 0.001077 0.060773 ( 0.060794)
Lazy is four times slower here, which is the point of lesson 103: the chain of blocks costs more than the array it avoids building on a hundred thousand items. The table is worth the minute it takes, because the difference is not the one a reader guesses.
TracePoint
TracePoint is Ruby watching itself. A trace on :call fires for every method call while it is enabled, and the event object names the method:
ruby -e 'tp = TracePoint.new(:call) { |t| puts t.method_id }; def a; end; tp.enable { a }'
a
Only a is printed, because the trace covers the block and the block calls one method. The event also carries path, lineno, defined_class and self, which is enough to build a call log. The other useful events are :return, :raise and :line.
A trace on :line over a large program is slow: every line runs a block. Enable it around the one call that needs watching, as above, instead of for the whole program.
GC.stat
When a program gets slower over time, the allocator is a suspect. GC.stat is a hash of counters, and heap_live_slots is the number of objects alive right now:
ruby -e 'p GC.stat[:heap_live_slots]'
23020
A bare Ruby already holds a few thousand objects, so the absolute number says little. Read it twice, around the work: if the live slots climb by the size of the input on every iteration, something is kept that could be released. GC.stat[:total_allocated_objects] and GC.stat[:minor_gc_count] answer the related questions of how much was allocated and how often the collector ran.
A profiler
A stopwatch says a block is slow; a profiler says which line inside it. stackprof samples the stack and writes a dump that it can report on. The gem builds a native extension, so these commands ran on the host in the ruby:3.4 image:
gem install stackprof
1 gem installed
ruby -r stackprof -e 'StackProf.run(mode: :cpu, out: "/tmp/stackprof.dump") { 100_000.times { |i| i.to_s } }'
That command prints nothing and exits 0: the samples are in the dump, and the report reads them:
stackprof /tmp/stackprof.dump --text
================================== Mode: cpu(1000) Samples: 37 (0.00% miss rate) GC: 12 (32.43%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 15 (40.5%) 15 (40.5%) Integer#to_s 9 (24.3%) 9 (24.3%) (sweeping) 21 (56.8%) 6 (16.2%) block (2 levels) in <main> 25 (67.6%) 4 (10.8%) Integer#times 3 (8.1%) 3 (8.1%) (marking) 25 (67.6%) 0 (0.0%) block in <main> 25 (67.6%) 0 (0.0%) StackProf.run 25 (67.6%) 0 (0.0%) <main> 12 (32.4%) 0 (0.0%) (garbage collection)
SAMPLES is the time spent in that frame itself; TOTAL adds the frames it called, so a method near the bottom of the list can still own most of the run. Here the top frame, Integer#to_s, is 40% and garbage collection is another third, which is the answer a stopwatch could not give: the loop spends its time converting integers and collecting them, not in times.
For a Rails application, rack-mini-profiler and the development log give the same information per request.
What to watch for
A benchmark of a method that does nothing is a benchmark of the
optimizer. Measure the real input, or a smaller version of it, and keep
the data in the same shape.
A profile from a development machine answers a different question from a
profile in production. The slow path is often I/O or a database call, and
neither appears in a CPU profile; measure the wall clock around the call
before reaching for a sampling profiler.
Next: Files and IO
Article author: Arthur Isaev