Profiling a slow script

Measure first

A slow script has one or two expensive lines, and guessing which is the first mistake. Start with a benchmark that runs the suspect code twice, once as written and once with the replacement:

require "benchmark" Benchmark.bm(12) do |x| x.report("concat") { out = ""; 50_000.times { out += "x" } } x.report("append") { out = +""; 50_000.times { out << "x" } } end

ruby bench.rb

user system total real concat 0.519638 0.988631 1.508269 ( 1.513817) append 0.011941 0.002910 0.014851 ( 0.014855)

The first line allocates a new string and copies the old one on every iteration, so the work grows with the square of the count. The second appends in place. One hundred times faster is the answer a profile would take an hour to reach.

The fix

The fix in the real code is one character:

# before report += format("%-10s %d\n", name, count) # after report << format("%-10s %d\n", name, count)

<< appends to the same string; += is report = report + ... and copies the whole string. The same trap appears with join in a loop instead of one join at the end, and with an array that is converted to a string on every iteration.

Measure again

A fix without a second measurement is a guess with a story. Run the same benchmark on the changed code and compare the real column; a change that moves five percent is noise on this machine, and a change that moves ninety is a result.

The second measurement also catches the fix that moved the cost: a string built once is faster, and a memory profile now shows one large string instead of a hundred thousand small ones. Whether that is better depends on what the report does next.

A flame graph

When the slow code is not obvious, a sampling profiler shows where the time went. stackprof writes a dump and the report groups the samples by frame:

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 } }'

stackprof /tmp/stackprof.dump --text

The gem builds a native extension, so these three commands ran on the host in the ruby:3.4 image; lesson 118 shows the report they print. Read SAMPLES as the time in the frame itself and TOTAL as the time including its calls; the leaf with the largest sample count is the line to change.

A flame graph in a browser is the same data drawn as nested bars. The wide bar at the bottom is the whole program; the wide bar near the top is the function that owns the time.

What to watch for

A micro-benchmark measures the loop and not the program. A method that is fast in isolation can still dominate a request because it is called a thousand times; a profiler shows the call count and the total.

Optimise the line the profile names, not the line that looks slow. Sorting one array of ten items is cheap even when it looks like the expensive step; the network call before it is usually the answer.

Next: Pattern matching in depth

Article author: Arthur Isaev