diff --git a/harness/gc.rb b/harness/gc.rb index d3138aaa..7d68d5d2 100644 --- a/harness/gc.rb +++ b/harness/gc.rb @@ -16,6 +16,7 @@ def realtime def run_benchmark(_num_itrs_hint, **, &block) times = [] + side_exit_counts = [] rss_samples = [] marking_times = [] sweeping_times = [] @@ -80,6 +81,9 @@ def run_benchmark(_num_itrs_hint, **, &block) gc_heap_deltas << sample["gc_stat_heap_delta"] gc_total_time_ns << sample["gc_total_time_ns"] total_time += time + + last_side_exit_count = side_exit_counts.last || 0 + side_exit_counts << RubyVM::ZJIT.stats(:side_exit_count) - last_side_exit_count end until num_itrs >= WARMUP_ITRS + MIN_BENCH_ITRS and total_time >= MIN_BENCH_TIME warmup_range = 0...WARMUP_ITRS @@ -108,6 +112,8 @@ def run_benchmark(_num_itrs_hint, **, &block) extra["gc_total_time_warmup"] = gc_total_time_ms[warmup_range] extra["gc_total_time_bench"] = gc_total_time_ms[bench_range] end + extra["side_exit_count_warmup"] = side_exit_counts[warmup_range] + extra["side_exit_count_bench"] = side_exit_counts[bench_range] # Snapshot heap utilisation after benchmark if GC.respond_to?(:stat_heap) diff --git a/misc/zjit_diff.rb b/misc/zjit_diff.rb index 1b4acda5..9151f65f 100755 --- a/misc/zjit_diff.rb +++ b/misc/zjit_diff.rb @@ -6,6 +6,9 @@ # By default some categories limit how many entries are shown # and some results only appear when the comparison passes a threshold. # Pass --help to see options. +# +# If the results were recorded with the GC harness (--harness=gc), iteration +# timings are also compared with GC time removed. require 'json' require_relative '../lib/ractor_breakdown' @@ -15,6 +18,9 @@ class ZjitDiff DEFAULT_MINIMUM_DIFF = 100 # Minimum absolute difference to report DEFAULT_LIMIT = nil # Show all by default (nil = no limit) + # Per-iteration GC times (ms) recorded by harness-gc + GC_TIME_KEYS = %w[gc_marking_time_bench gc_sweeping_time_bench].freeze + # Categories matching zjit.rb stats_string output order STAT_CATEGORIES = [ { prefix: 'not_inlined_cfuncs_', prompt: 'not inlined C methods', limit: 10 }, @@ -102,6 +108,7 @@ def run print_header print_benchmark_timings + print_benchmark_timings_without_gc print_memory_usage print_send_counters print_summary_counters @@ -213,26 +220,79 @@ def print_benchmark_timings next if stats.empty? - baseline = stats.first - fastest = stats.min_by { |s| s[:avg] } + print_timing_rows(stats) + end + puts + end - stats.each do |s| - diff_pct = ((s[:avg] - baseline[:avg]) / baseline[:avg] * 100) - is_fastest = s == fastest && stats.size > 1 - marker = is_fastest ? '★' : ' ' - if s == baseline - printf " %-20s avg: %7.3fs min: %7.3fs %s (baseline)\n", - s[:ruby], s[:avg], s[:min], marker - else - slower_faster = diff_pct > 0 ? 'slower' : 'faster' - printf " %-20s avg: %7.3fs min: %7.3fs %s %+7.1f%% (%s)\n", - s[:ruby], s[:avg], s[:min], marker, diff_pct, slower_faster - end + # Iterations are supposed to do the same work, but GC heuristics move work + # between them: garbage left by earlier iterations is marked and (lazily) + # swept during later ones. Subtracting each iteration's GC time compares + # the time spent outside the GC, which doesn't depend on where the GC + # happened to run. + def print_benchmark_timings_without_gc + any_printed = false + + benchmarks.each do |bench_name| + stats = @ruby_names.map do |ruby| + times = @raw_data.dig(ruby, bench_name, 'bench') || [] + next nil if times.empty? + gc_times = gc_seconds_per_iteration(ruby, bench_name, times.size) + next nil unless gc_times + without_gc = times.zip(gc_times).map { |time, gc| time - gc } + gc_avg = gc_times.sum / gc_times.size + { ruby: ruby, avg: without_gc.sum / without_gc.size, min: without_gc.min, + gc_avg: gc_avg, gc_pct: gc_avg / (times.sum / times.size) * 100 } + end.compact + + # Without the baseline's GC times there is nothing to compare against + next unless stats.size > 1 && stats.first[:ruby] == @ruby_names.first + + unless any_printed + puts "BENCHMARK TIMINGS WITHOUT GC TIME (lower is better)" + puts "-" * 80 + any_printed = true end + + puts " #{bench_name}:" + print_timing_rows(stats) end + + return unless any_printed + puts " gc: average GC (marking + sweeping) time per iteration, and its share of the iteration." + puts " GC.stat reports whole milliseconds, so min is approximate; avg is not affected." puts end + # Seconds of GC time (marking + sweeping) in each benchmark iteration, + # or nil if the results were not recorded with harness-gc. + def gc_seconds_per_iteration(ruby, bench_name, size) + bench_data = @raw_data.dig(ruby, bench_name) || {} + series = GC_TIME_KEYS.map { |key| bench_data[key] } + return nil unless series.all? { |ms| ms.is_a?(Array) && ms.size == size } + series.transpose.map { |ms| ms.sum / 1000.0 } + end + + def print_timing_rows(stats) + baseline = stats.first + fastest = stats.min_by { |s| s[:avg] } + + stats.each do |s| + diff_pct = ((s[:avg] - baseline[:avg]) / baseline[:avg] * 100) + is_fastest = s == fastest && stats.size > 1 + marker = is_fastest ? '★' : ' ' + gc = s[:gc_avg] ? format(" gc: %7.3fs (%3.0f%%)", s[:gc_avg], s[:gc_pct]) : '' + if s == baseline + printf " %-20s avg: %7.3fs min: %7.3fs%s %s (baseline)\n", + s[:ruby], s[:avg], s[:min], gc, marker + else + slower_faster = diff_pct > 0 ? 'slower' : 'faster' + printf " %-20s avg: %7.3fs min: %7.3fs%s %s %+7.1f%% (%s)\n", + s[:ruby], s[:avg], s[:min], gc, marker, diff_pct, slower_faster + end + end + end + def print_memory_usage puts "MEMORY USAGE" puts "-" * 80