Record the marking time of each minor and major GC in harness-gc

README.md

@@ -536,6 +536,12 @@ data when it is zero or `N/A` in every row.
   Ractors started, so each cycle counts once in the sum. Single-executable
   reports also show `GC ms/worker`, which divides each iteration's worker-sum
   GC time by its sampled worker count, then averages.
+* On Ruby 4.1 and newer, `--harness=gc` also records the marking time of
+  each collection from `GC::Profiler`. `mark ms/minor` and `mark ms/major`
+  (and the `mark/minor` and `mark/major` ratios) average it per iteration,
+  then over iterations, so a major GC in one iteration does not move the
+  minor column. Root-marking changes show up there more clearly than in
+  `mark/iter`.
 * `compacts*` shows the main Ractor's
   `GC.stat(:compact_count)` delta. Every global compacting cycle increments
   it in every object space, so it is not summed across workers.

harness/gc.rb

@@ -25,12 +25,20 @@ def run_benchmark(_num_itrs_hint, **, &block)
   global_counts = []
   gc_heap_deltas = []
   gc_total_time_ns = []
+  minor_marking_times = []
+  major_marking_times = []
   total_time = 0
   num_itrs = 0
 
   has_marking = GC.stat.key?(:marking_time)
   has_sweeping = GC.stat.key?(:sweeping_time)
   has_global_gc = GCStats.stat_available?(:global_gc_invocation_count)
+  has_records = GCStats.collection_records_supported?
+  if has_records
+    profiler_was_enabled = GC::Profiler.enabled?
+    GC::Profiler.enable unless profiler_was_enabled
+    record_seq = GC::Profiler.raw_data(limit: 1).last&.fetch(:GC_SEQUENCE)
+  end
 
   header = "itr:   time"
   header << "   marking" if has_marking
@@ -80,6 +88,14 @@ 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
+
+    if has_records
+      minor_ms, major_ms, record_seq = GCStats.marking_times_since(record_seq)
+      # A global GC's record has no major_by even when it marks fully.
+      minor_ms = major_ms = nil if global_delta.to_i > 0
+      minor_marking_times << minor_ms
+      major_marking_times << major_ms
+    end
   end until num_itrs >= WARMUP_ITRS + MIN_BENCH_ITRS and total_time >= MIN_BENCH_TIME
 
   warmup_range = 0...WARMUP_ITRS
@@ -109,6 +125,12 @@ def run_benchmark(_num_itrs_hint, **, &block)
     extra["gc_total_time_bench"] = gc_total_time_ms[bench_range]
   end
 
+  if has_records
+    GC::Profiler.disable unless profiler_was_enabled
+    extra["gc_minor_marking_times_bench"] = minor_marking_times[bench_range]
+    extra["gc_major_marking_times_bench"] = major_marking_times[bench_range]
+  end
+
   # Snapshot heap utilisation after benchmark
   if GC.respond_to?(:stat_heap)
     GC.start(full_mark: true)

lib/benchmark_runner.rb

@@ -96,6 +96,9 @@ def build_output_text(ruby_descriptions, table, format, bench_failures, include_
           output_str << "- GC time ratios are #{base_name}/comparison; above 1 means the comparison spent less GC time.\n"
           output_str << "- gc/iter, mark/iter, and sweep/iter compare total GC (or phase) time per benchmark iteration, so they include both per-GC cost and GC frequency changes.\n"
           output_str << "- gc/GC, mark/GC, and sweep/GC divide average GC (or phase) time by the same run's GCs/iter count; they are not complete per-cycle attribution of process-wide GC.\n"
+          if sections.any? { |section| Array(section[:gc_tables]).any? { |gc_table| gc_table[:rows].first.include?('mark/minor') } }
+            output_str << "- mark/minor and mark/major compare the marking time of one minor or one major collection (GC::Profiler records, Ruby 4.1+), averaged per iteration. A change to root marking shows here even when a major GC lands in a different iteration; changes in how many objects are young or remembered move them too, so read them with GC counts.\n"
+          end
           output_str << "- GC counts show #{base_name} → comparison values, not ratios. Rows with no GC activity are omitted.\n"
         end
         if has_memory_summary

lib/gc_stats.rb

@@ -124,6 +124,39 @@ def delta(before, after)
     sample
   end
 
+  # GC::Profiler.raw_data(since:) and its per-collection wall times are new
+  # in Ruby 4.1. TruffleRuby and modular GCs have no raw_data.
+  def collection_records_supported?
+    return false unless defined?(GC::Profiler) && GC::Profiler.respond_to?(:raw_data)
+
+    GC::Profiler.raw_data(since: 0, limit: 0)
+    true
+  rescue ArgumentError
+    false
+  end
+
+  # The marking time in ms of each collection that finished marking after the
+  # record numbered +seq+ (nil before the first call), split into minor and
+  # major collections. A collection that is still marking is left for the
+  # next call. Returns [minor_ms, major_ms, seq]; the lists are nil if
+  # records were dropped or the profiler is off.
+  def marking_times_since(seq, marking: nil, records: nil)
+    if records.nil?
+      marking = GC.latest_gc_info(:state) == :marking
+      records = GC::Profiler.raw_data(**(seq ? { since: seq } : {}))
+      return [nil, nil, seq] unless records
+
+      marking ||= GC.latest_gc_info(:state) == :marking
+    end
+    records = records[0...-1] if marking
+    return [[], [], seq] if records.empty?
+
+    complete = seq.nil? || records.first[:GC_SEQUENCE] == seq + 1
+    minor, major = records.partition { |record| record[:GC_FLAGS][:major_by].nil? }
+    ms = ->(list) { list.map { |record| record[:GC_MARK_WALL_TIME] * 1000.0 } if complete }
+    [ms.(minor), ms.(major), records.last[:GC_SEQUENCE]]
+  end
+
   def with_measure_total_time
     has_measure = GC.respond_to?(:measure_total_time) && GC.respond_to?(:measure_total_time=)
     saved = GC.measure_total_time if has_measure

lib/results_table_builder.rb

@@ -144,6 +144,8 @@ def build_gc_comparison_tables(label_header)
           count: gc_count_series(data),
           global: data['gc_global_count_bench'],
           compact: data['gc_controller_compact_count_bench'],
+          minor_mark: collection_series(data, 'gc_minor_marking_times_bench'),
+          major_mark: collection_series(data, 'gc_major_marking_times_bench'),
         }
       end
 
@@ -173,6 +175,10 @@ def gc_ratio_columns
     columns << ["sweep/iter", ->(base, other) { ratio_cell(gc_ratio(base[:sweep], other[:sweep])) }]
     columns << ["mark/GC", ->(base, other) { ratio_cell(per_gc_ratio(base, other, :mark)) }]
     columns << ["sweep/GC", ->(base, other) { ratio_cell(per_gc_ratio(base, other, :sweep)) }]
+    if gc_series_present?('gc_minor_marking_times_bench')
+      columns << ["mark/minor", ->(base, other) { ratio_cell(gc_ratio(base[:minor_mark], other[:minor_mark])) }]
+      columns << ["mark/major", ->(base, other) { ratio_cell(gc_ratio(base[:major_mark], other[:major_mark])) }]
+    end
     columns
   end
 
@@ -210,6 +216,10 @@ def gc_absolute_columns
       ["major/iter", ->(data) { mean_cell(data['gc_major_count_bench']) }],
       ["minor/iter", ->(data) { mean_cell(data['gc_minor_count_bench']) }],
     ]
+    if gc_series_present?('gc_minor_marking_times_bench')
+      columns << ["mark ms/minor", ->(data) { mean_cell(collection_series(data, 'gc_minor_marking_times_bench'), precise: true) }]
+      columns << ["mark ms/major", ->(data) { mean_cell(collection_series(data, 'gc_major_marking_times_bench'), precise: true) }]
+    end
     if gc_series_present?('gc_global_count_bench')
       columns << ["global/iter", ->(data) { mean_cell(data['gc_global_count_bench']) }]
     end
@@ -495,6 +505,16 @@ def gc_count_series(data)
     major.zip(minor).map { |a, b| a + b }
   end
 
+  # The mean per-collection time of each iteration that ran such a
+  # collection. Collections within an iteration share heap state, so the
+  # iteration, not the collection, is the sample for p-values.
+  def collection_series(data, key)
+    values = data[key]
+    return nil unless values.is_a?(Array) && values.all?(Array)
+
+    values.reject(&:empty?).map { |times| times.sum / times.size }
+  end
+
   def gc_time_per_gc(time, count)
     return nil unless numeric_series?(time) && numeric_series?(count) && time.length == count.length
 

test/gc_stats_test.rb

@@ -110,6 +110,70 @@ def snapshot(count:, major:, minor:, marking: nil, sweeping: nil, total_ns: nil,
     end
   end
 
+  describe '.marking_times_since' do
+    def record(seq, major, mark)
+      { GC_SEQUENCE: seq, GC_FLAGS: { major_by: major }, GC_MARK_WALL_TIME: mark }
+    end
+
+    it 'splits the marking time of each new collection into minor and major' do
+      records = [record(5, nil, 0.001), record(6, :oldgen, 0.020), record(7, nil, 0.003)]
+
+      minor, major, seq = GCStats.marking_times_since(4, records: records, marking: false)
+
+      assert_equal [1.0, 3.0], minor.map { |ms| ms.round(6) }
+      assert_equal [20.0], major.map { |ms| ms.round(6) }
+      assert_equal 7, seq
+    end
+
+    it 'leaves a collection that is still marking for the next call' do
+      records = [record(5, nil, 0.001), record(6, :nofree, 0.004)]
+
+      minor, major, seq = GCStats.marking_times_since(4, records: records, marking: true)
+
+      assert_equal [1.0], minor.map { |ms| ms.round(6) }
+      assert_equal [], major
+      assert_equal 5, seq
+    end
+
+    it 'reports nothing rather than a partial list when records were dropped' do
+      minor, major, seq = GCStats.marking_times_since(4, records: [record(9, nil, 0.001)], marking: false)
+
+      assert_nil minor
+      assert_nil major
+      assert_equal 9, seq
+    end
+
+    it 'takes every record on the first call, whatever its sequence number' do
+      minor, _major, seq = GCStats.marking_times_since(nil, records: [record(9, nil, 0.002)], marking: false)
+
+      assert_equal [2.0], minor.map { |ms| ms.round(6) }
+      assert_equal 9, seq
+    end
+
+    it 'splits real minor and major collections' do
+      skip 'GC::Profiler.raw_data(since:) is new in Ruby 4.1' unless GCStats.collection_records_supported?
+
+      was_enabled = GC::Profiler.enabled?
+      GC::Profiler.enable
+      # A pending major (GC.latest_gc_info(:need_major_by)) would turn the minor into a major.
+      GC.start(full_mark: true, immediate_mark: true, immediate_sweep: true)
+      _, _, seq = GCStats.marking_times_since(nil)
+      GC.start(full_mark: false, immediate_mark: true, immediate_sweep: true)
+      GC.start(full_mark: true, immediate_mark: true, immediate_sweep: true)
+      minor, major, = GCStats.marking_times_since(seq)
+
+      assert_equal 1, minor.size
+      assert_equal 1, major.size
+      assert_operator major.first, :>, 0.0
+    ensure
+      GC::Profiler.disable unless was_enabled
+    end
+
+    it 'keeps the sequence when no collection finished' do
+      assert_equal [[], [], 4], GCStats.marking_times_since(4, records: [], marking: false)
+    end
+  end
+
   describe '.aggregate' do
     it 'raises ArgumentError for an empty sample set' do
       error = assert_raises(ArgumentError) { GCStats.aggregate([]) }

test/results_table_builder_test.rb

@@ -800,6 +800,46 @@ def scenario_layout(name, counts)
       assert_nil gc_tables
     end
 
+    it 'compares the marking time of one minor and one major collection' do
+      blob = ->(minor, major, minor_times, major_times) do
+        {
+          'warmup' => [], 'bench' => [0.1, 0.1], 'rss' => 10,
+          'gc_marking_time_bench' => [10.0, 10.0], 'gc_sweeping_time_bench' => [1.0, 1.0],
+          'gc_major_count_bench' => major, 'gc_minor_count_bench' => minor,
+          'gc_minor_marking_times_bench' => minor_times, 'gc_major_marking_times_bench' => major_times,
+        }
+      end
+      base = blob.call([2, 1], [1, 0], [[1.0, 3.0], [2.0]], [[8.0], []])
+      exp = blob.call([1, 1], [0, 1], [[0.5], [1.5]], [[], [16.0]])
+      partial = blob.call([1, 1], [0, 1], [nil, [1.5]], [nil, [16.0]])
+      builder = ResultsTableBuilder.new(
+        executable_names: ['ruby-base', 'ruby-exp', 'ruby-partial'],
+        bench_data: { 'ruby-base' => { 'fib' => base }, 'ruby-exp' => { 'fib' => exp }, 'ruby-partial' => { 'fib' => partial } }
+      )
+
+      _table, _format, gc_tables = builder.build
+
+      ratios = gc_tables.first
+      assert_equal ['bench', 'comparison', 'mark/iter', 'sweep/iter', 'mark/GC', 'sweep/GC', 'mark/minor', 'mark/major'], ratios[:rows][0]
+      # mark/GC mixes the two kinds: fewer collections per iteration make it 0.750.
+      assert_equal ['fib', 'ruby-exp', '1.000', '1.000', '0.750', '0.750', '2.000', '0.500'], ratios[:rows][1]
+      assert_equal ['N/A', 'N/A'], ratios[:rows][2].last(2), 'an iteration without records makes the series unavailable'
+    end
+
+    it 'averages the marking time per collection within each iteration first' do
+      blob = {
+        'warmup' => [], 'bench' => [0.1, 0.1], 'rss' => 10,
+        'gc_major_count_bench' => [0, 0], 'gc_minor_count_bench' => [2, 1],
+        'gc_minor_marking_times_bench' => [[1.0, 2.0], [6.0]], 'gc_major_marking_times_bench' => [[], []],
+      }
+      builder = ResultsTableBuilder.new(executable_names: ['ruby'], bench_data: { 'ruby' => { 'fib' => blob } })
+
+      _table, _format, gc_tables = builder.build
+
+      assert_equal [['bench', 'GCs/iter', 'minor/iter', 'mark ms/minor'], ['fib', '1.5', '1.5', '3.750']], gc_tables.first[:rows]
+      assert_includes gc_tables.first[:hidden], 'mark ms/major'
+    end
+
     it 'builds a non-Ractor absolute GC table and hides a column that is zero in every row' do
       bench_data = {
         'ruby' => {