From 878f4823a14e0df50ebdc14f01939127cfe42cb4 Mon Sep 17 00:00:00 2001 From: Takashi Kokubun Date: Wed, 21 Dec 2022 14:00:06 -0800 Subject: [PATCH 1/4] Add harness-cstats to collect C method stats --- README.md | 1 + harness-cstats/harness.rb | 38 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 39 insertions(+) create mode 100644 harness-cstats/harness.rb diff --git a/README.md b/README.md index ad616746..a2eec65f 100644 --- a/README.md +++ b/README.md @@ -139,6 +139,7 @@ You can find several test harnesses in this repository: * harness-perf - a simplified harness that runs for exactly the hinted number of iterations * harness-bips - a harness that measures iterations/second until stable * harness-continuous - a harness that adjusts the batch sizes of iterations to run in stable iteration size batches +* harness-cstats - count C method calls and C loop iterations To use it, run a benchmark script directly, specifying a harness directory with `-I`: diff --git a/harness-cstats/harness.rb b/harness-cstats/harness.rb new file mode 100644 index 00000000..7a2761a9 --- /dev/null +++ b/harness-cstats/harness.rb @@ -0,0 +1,38 @@ +require_relative '../harness/harness' + +# Using Module#prepend to enable TracePoint right before #run_benchmark +# while also reusing the original implementation. +self.singleton_class.prepend Module.new { + def run_benchmark(*) + c_calls = Hash.new { 0 } + c_loops = Hash.new { 0 } + + trace_point = TracePoint.new(:c_call) do |tp| + method_name = "#{tp.defined_class}##{tp.method_id}" + c_calls[method_name] += 1 + + case tp.method_id + when /(\A|_)each(_|\z)/, /(\A|_)map\!?\z/ + c_loops[method_name] += tp.self.size if tp.self.respond_to?(:size) + when 'times' + c_loops[method_name] += Integer(tp.self) + end + end + + trace_point.enable + super + ensure + trace_point.disable + + puts "Top C loop method iterations:" + c_loops.sort_by(&:last).reverse_each do |method, count| + puts '%8d %s' % [count, method] + end + puts + + puts "Top 100 C method calls:" + c_calls.sort_by(&:last).reverse[0...100].each do |method, count| + puts '%8d %s' % [count, method] + end + end +} From 27cb7e066b2d832417d37581e18ffd67d6e8fc4f Mon Sep 17 00:00:00 2001 From: Takashi Kokubun Date: Wed, 21 Dec 2022 14:19:39 -0800 Subject: [PATCH 2/4] Include Kernel#loop --- harness-cstats/harness.rb | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/harness-cstats/harness.rb b/harness-cstats/harness.rb index 7a2761a9..21e4eba5 100644 --- a/harness-cstats/harness.rb +++ b/harness-cstats/harness.rb @@ -14,8 +14,10 @@ def run_benchmark(*) case tp.method_id when /(\A|_)each(_|\z)/, /(\A|_)map\!?\z/ c_loops[method_name] += tp.self.size if tp.self.respond_to?(:size) - when 'times' + when :times c_loops[method_name] += Integer(tp.self) + when :loop + c_loops[method_name] += 1 # can't predict it properly end end @@ -31,7 +33,7 @@ def run_benchmark(*) puts puts "Top 100 C method calls:" - c_calls.sort_by(&:last).reverse[0...100].each do |method, count| + c_calls.sort_by(&:last).reverse.first(100).each do |method, count| puts '%8d %s' % [count, method] end end From f6da7864c0125eef7c48c31fa7f66f622989a065 Mon Sep 17 00:00:00 2001 From: Takashi Kokubun Date: Wed, 21 Dec 2022 15:20:39 -0800 Subject: [PATCH 3/4] Correctly measure Kernel#loop iterations --- harness-cstats/harness.rb | 42 ++++++++++++++++++++++++++------------- 1 file changed, 28 insertions(+), 14 deletions(-) diff --git a/harness-cstats/harness.rb b/harness-cstats/harness.rb index 21e4eba5..8e9714b9 100644 --- a/harness-cstats/harness.rb +++ b/harness-cstats/harness.rb @@ -4,29 +4,43 @@ # while also reusing the original implementation. self.singleton_class.prepend Module.new { def run_benchmark(*) + frames = [] c_calls = Hash.new { 0 } c_loops = Hash.new { 0 } - trace_point = TracePoint.new(:c_call) do |tp| - method_name = "#{tp.defined_class}##{tp.method_id}" - c_calls[method_name] += 1 - - case tp.method_id - when /(\A|_)each(_|\z)/, /(\A|_)map\!?\z/ - c_loops[method_name] += tp.self.size if tp.self.respond_to?(:size) - when :times - c_loops[method_name] += Integer(tp.self) - when :loop - c_loops[method_name] += 1 # can't predict it properly + 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 C method calls + if tp.event == :c_call + c_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 - trace_point.enable + method_trace.enable + block_trace.enable super ensure - trace_point.disable + block_trace.disable + method_trace.disable - puts "Top C loop method iterations:" + puts "Top C method block iterations:" c_loops.sort_by(&:last).reverse_each do |method, count| puts '%8d %s' % [count, method] end From ccf8b44ff424811372790e2dd6b65dbccf9956ce Mon Sep 17 00:00:00 2001 From: Takashi Kokubun Date: Wed, 21 Dec 2022 16:53:37 -0800 Subject: [PATCH 4/4] Show % out of total calls --- harness-cstats/harness.rb | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-) diff --git a/harness-cstats/harness.rb b/harness-cstats/harness.rb index 8e9714b9..f1a3b65b 100644 --- a/harness-cstats/harness.rb +++ b/harness-cstats/harness.rb @@ -40,15 +40,21 @@ def run_benchmark(*) block_trace.disable method_trace.disable - puts "Top C method block iterations:" - c_loops.sort_by(&:last).reverse_each do |method, count| - puts '%8d %s' % [count, method] + 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 - puts "Top 100 C method calls:" + 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 %s' % [count, method] + puts '%8d (%4.1f%%) %s' % [count, 100.0 * count / c_calls_total, method] end end }