Profiling

The previous lesson asked how many objects a block allocates. This lesson asks in which method a program does how much work, but with call counts, not with time. The course’s measuring axis does not change: what determines this result? This lesson’s observation is the hot path row, and its determinant is code.

Profiling is measuring where a program’s time or calls gather. M10/K03 measured how many times a piece of code ran. Profiling counts calls too, but here the class is not the count itself; it is what determines the count. The principles of comparative measurement and profiling were covered in M10/K05; this lesson measures two things using only Ruby’s standard library, with no product and no profiling tool: the number of method calls and the kind of time. The hot path is the most called method. The core’s determinant.rb file and this lesson’s excerpt profile.rb are given below as they are; both are source and have no output. hot_path in the excerpt counts calls with TracePoint; only the methods the program defines itself are counted.

# determinant.rb — a run model and a helper that classifies what determines a result

# Run: the three inputs a result may depend on. Everything outside these three is code.
Run = Data.define(:lock, :seed, :environment)

BASE = Run.new(
  lock: { "formatter" => "1.4.2", "parser" => "2.0.1" },
  seed: 1,
  environment: { clock: Time.utc(2026, 10, 16, 9, 0), cores: 4, variables: {} }
)

# Each variant changes a single input; the others stay as in the base.
VARIANTS = {
  dependency: BASE.with(lock: { "formatter" => "1.5.0", "parser" => "2.1.0" }),
  order: BASE.with(seed: 2),
  environment: BASE.with(environment: { clock: Time.utc(2027, 3, 1, 9, 0), cores: 8,
                                        variables: { "WORKER_COUNT" => "3" } })
}

# Rule: the computation runs first in the base, then once in each variant. The first variant
# that changes the result (dependency, order, environment, in that order) is the determinant;
# if none changes it, code.
def determinant(computation)
  base = computation.call(BASE)
  changed = VARIANTS.to_h { |name, run| [name, computation.call(run) != base] }
  kind = changed.key(true)&.to_s || "code"
  evidence = changed.map { |name, c| "#{name[0].upcase}#{c ? '+' : '-'}" }.join(" ")
  [kind, evidence, base]
end

# profile.rb — the calls of the methods the program defines are counted
# Profiling: calls to the methods the program defines are counted; the most called is the hot path.
def hot_path
  counts = Hash.new(0)
  trace = TracePoint.new(:call) { |t| counts[t.method_id] += 1 if t.defined_class == Object }
  trace.enable { yield }
  counts.max_by { |_, n| n }
end

def format_money(cents) = format("%d.%02d", cents / 100, cents % 100)
def format_line(line) = "#{line[:name]} #{format_money(line[:unit])} #{format_money(line[:total])}"
def report(lines) = lines.map { |l| format_line(l) }.join("\n")

Counting Calls

A report of a hundred lines is built: each line has a name, a unit price, and a total. report hands each line to format_line, which formats both the unit price and the total with format_money. The block below runs this report under TracePoint and extracts the call count of each method.

# count.rb — the call count of each method
require_relative "determinant"
require_relative "profile"

def call_counts
  counts = Hash.new(0)
  trace = TracePoint.new(:call) { |t| counts[t.method_id] += 1 if t.defined_class == Object }
  trace.enable { yield }
  counts.sort_by { |name, n| [-n, name] }
end

lines = Array.new(100) { |i| { name: "product#{i}", unit: 1250, total: 1250 * (i + 1) } }
p call_counts { report(lines) }
p hot_path { report(lines) }
p determinant(->(_r) { hot_path { report(lines) } })

[[:format_money, 200], [:format_line, 100], [:report, 1]]
[:format_money, 200]
["code", "D- O- E-", [:format_money, 200]]

format_money was called two hundred times: each of the hundred lines called it twice. format_line was called a hundred times and report once. The second line is the hot_path result, that is, the most called method and its count. The third line runs the rule: the versions in the lock file, the seed, and the environment changed, and the result did not; the determinant is code. The call count comes from the number of lines in the report and from how the methods call one another; both are the work of the code. RU13. The defined_class == Object filter counts only the methods defined at the top level; methods in other classes do not enter this count.

The filter selects only the program’s own methods. Ruby’s own built-in methods do not produce the :call event, they produce the :c_call event. Counting the same report with :c_call shows which built-in methods are hot.

# builtin.rb — the call counts of the built-in methods
require_relative "profile"

lines = Array.new(100) { |i| { name: "product#{i}", unit: 1250, total: 1250 * (i + 1) } }
counts = Hash.new(0)
trace = TracePoint.new(:c_call) { |t| counts[t.method_id] += 1 }
trace.enable { report(lines) }
p counts.sort_by { |name, n| [-n, name] }.first(5)

[[:[], 300], [:%, 200], [:/, 200], [:format, 200], [:join, 1]]

The most called built-in method was []: each line indexes the name, the unit price, and the total, three times. %, /, and format came two hundred times each, because format_money was called two hundred times and every call did one division, one remainder, and one format. The counts reflect the structure of the code; if we doubled the number of lines, all the counts that depend on lines would double. RU14. The sixth place and beyond are not shown here; the join in fifth place was called once, and the rest do not come out of this count.

A Fix and a New Count

Once the hot path is found, the first question is whether all these calls are needed. In the report the unit price is the same on every line, and printing it once is enough. The fixed version formats the total once per line.

# fix.rb — format_money is called once per line
require_relative "profile"

def format_line_short(line) = "#{line[:name]} #{format_money(line[:total])}"
def report_short(lines) = lines.map { |l| format_line_short(l) }.join("\n")

def call_counts
  counts = Hash.new(0)
  trace = TracePoint.new(:call) { |t| counts[t.method_id] += 1 if t.defined_class == Object }
  trace.enable { yield }
  counts.sort_by { |name, n| [-n, name] }
end

lines = Array.new(100) { |i| { name: "product#{i}", unit: 1250, total: 1250 * (i + 1) } }
p call_counts { report_short(lines) }

[[:format_line_short, 100], [:format_money, 100], [:report_short, 1]]

format_money is now called a hundred times and has fallen to the same count as format_line_short. The hot path stopped being a single method: two methods are called equally. The fix halved the calls but did not settle the question of which one is slow. RU15. This measurement shows that the call count was halved; it does not show that the time was halved too.

The Bounding Measurement

The call count says which method works the most; it does not say which method is the slowest. A method can be called a hundred times and take long on each call, while another is called two hundred times and takes little each time. Time is a separate measurement and has a separate determinant. Two tools measure time: Benchmark.realtime and Process.clock_gettime(Process::CLOCK_MONOTONIC). Both return a floating-point number; the number itself is not printed, because it differs on every run and on every machine.

# timing.rb — two tools that measure time, both return a Float
require "benchmark"
require_relative "profile"

lines = Array.new(100) { |i| { name: "product#{i}", unit: 1250, total: 1250 * (i + 1) } }
p Benchmark.realtime { report(lines) }.class
p Process.clock_gettime(Process::CLOCK_MONOTONIC).class

Float
Float

Both tools returned a Float; their values were not printed. If a measurement rests on time and the result is “which is slowest”, the determinant is the environment: if the machine is loaded, if the core is different, or if the cache has warmed up, the ranking changes. The call count is the work of the code, so it comes out the same everywhere. The two do not answer the same question: the answer to which one works more is in the code; the answer to which one takes more time is in the machine.

This is the lesson’s bound: the hot path is determined by the call count and classified as code, but “the slowest” lies outside this classification. RU16. The time measurement was shown here only by its type; which method is really the slowest was not measured in this lesson and must not be inferred from the call count.

Summary

• The call counts of the program’s own methods are counted with TracePoint on the :call event; built-in methods are counted separately with :c_call.
• The call count determines the hot path, and the code determines the call count: the rule found the same method in all three variants.
• A new count is taken after a fix; the hot path can spread from a single method to several.
• Time is measured with Benchmark.realtime or Process.clock_gettime and depends on the environment; the call count and the time do not answer the same question.

Next Step

The code, the call counts, and the allocated objects have been measured; in hand there is an application whose release is to be cut. The last lesson queries the three things inside a release, the asset name, the release directory, and the manifest, one by one, and finds the determinant of each.