zjit_diff: compare iteration timings with GC time removed

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)

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