Count Ruby method calls as well in stats harness #163
Conversation
|
I like it and I think this is very useful 👍 One thing that I find a bit confusing though: Here I'm not sure what the block calls count mean. Based on the name it sounds like the number of times a block has been called. However, the numbers seem much too low. That is, it seems improbable that a block inside So I'm assuming that |
The numbers seem to come from
If you have this code: total = 0
run_benchmark do
[1, 2, 3, 4, 5].each do |i|
total += i
end
end
puts "total: #{total}"you get: and I think it's working as I intended; it's counting the call of Full script used for testingdef run_benchmark
frames = []
c_calls = Hash.new { 0 }
c_loops = Hash.new { 0 }
rb_calls = Hash.new { 0 }
method_trace = TracePoint.new(:call, :c_call, :return, :c_return) do |tp|
# Keep track of call frames to get the caller of :b_call
case tp.event
when :call, :c_call
method_name = "#{tp.defined_class}##{tp.method_id}"
frames.push([tp.event, method_name])
when :return, :c_return
frames.pop
end
# Count method calls
case tp.event
when :c_call
c_calls[method_name] += 1
when :call
rb_calls[method_name] += 1
end
end
block_trace = TracePoint.new(:b_call) do |tp|
caller_event, caller_method = frames.last
# Count block calls only when the caller is a C method
if caller_event == :c_call
c_loops[caller_method] += 1
end
end
method_trace.enable
block_trace.enable
yield
ensure
block_trace.disable
method_trace.disable
c_loops_total = c_loops.sum(&:last)
c_loops = c_loops.sort_by { |_method, count| -count }.first(100)
c_loops_ratio = 100.0 * c_loops.sum(&:last) / c_loops_total
puts "Top #{c_loops.size} block calls by C methods (#{'%.1f' % c_loops_ratio}% of all #{c_loops_total} calls):"
c_loops.each do |method, count|
puts '%8d (%4.1f%%) %s' % [count, 100.0 * count / c_loops_total, method]
end
puts
c_calls_total = c_calls.sum(&:last)
c_calls = c_calls.sort_by { |_method, count| -count }.first(100)
c_calls_ratio = 100.0 * c_calls.sum(&:last) / c_calls_total
puts "Top #{c_calls.size} C method calls (#{'%.1f' % c_calls_ratio}% of all #{c_calls_total} calls):"
c_calls.sort_by(&:last).reverse.first(100).each do |method, count|
puts '%8d (%4.1f%%) %s' % [count, 100.0 * count / c_calls_total, method]
end
puts
rb_calls_total = rb_calls.sum(&:last)
rb_calls = rb_calls.sort_by { |_method, count| -count }.first(100)
rb_calls_ratio = 100.0 * rb_calls.sum(&:last) / rb_calls_total
puts "Top #{rb_calls.size} Ruby method calls (#{'%.1f' % rb_calls_ratio}% of all #{rb_calls_total} calls):"
rb_calls.sort_by(&:last).reverse.first(100).each do |method, count|
puts '%8d (%4.1f%%) %s' % [count, 100.0 * count / rb_calls_total, method]
end
end
total = 0
run_benchmark do
[1, 2, 3, 4, 5].each do |i|
total += i
end
end
puts "total: #{total}" |
|
Then my intuition is wrong and there are way more C calls and Ruby calls than block calls. I will merge this, but I think it could also be useful to add a breakdown of C calls, Ruby calls and block calls with the percentage for each, just to guide our optimization efforts. At the moment it seems like we might be spending a lot less time doing loop iterations than we thought? |
2 participants
This PR adds Ruby stats to the harness created in #158.
It seems useful to know about Ruby call stats as well when we discuss method inlining implementation.
Example
activerecord
hexapdf
liquid-render
mail
psych-load
railsbench
ruby-lsp