diff --git a/README.md b/README.md index 44f346bd..94e3d159 100644 --- a/README.md +++ b/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. diff --git a/harness/gc.rb b/harness/gc.rb index d3138aaa..59b72e1f 100644 --- a/harness/gc.rb +++ b/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) diff --git a/lib/benchmark_runner.rb b/lib/benchmark_runner.rb index 43c427ff..a7185011 100644 --- a/lib/benchmark_runner.rb +++ b/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 diff --git a/lib/gc_stats.rb b/lib/gc_stats.rb index a794971c..d7bbf094 100644 --- a/lib/gc_stats.rb +++ b/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 diff --git a/lib/results_table_builder.rb b/lib/results_table_builder.rb index 6f48a09a..67f569bf 100644 --- a/lib/results_table_builder.rb +++ b/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 diff --git a/test/gc_stats_test.rb b/test/gc_stats_test.rb index 2fcb5308..b6245276 100644 --- a/test/gc_stats_test.rb +++ b/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([]) } diff --git a/test/results_table_builder_test.rb b/test/results_table_builder_test.rb index c0ad30f3..80f2ce11 100644 --- a/test/results_table_builder_test.rb +++ b/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' => {