diff --git a/README.md b/README.md index db115f02..f761c00f 100644 --- a/README.md +++ b/README.md @@ -322,9 +322,10 @@ The summary table adds these columns: * `(worker sum)` columns add the Ractor-local counters of the sampled workers of each iteration. `GCs/iter` is the sum of `minor/iter`, `major/iter`, and `global/iter`; a global cycle counts under `global` on - the Ractor that initiated it, not under `major`. Single-executable reports - also show `GC ms/worker`, which divides each iteration's worker-sum GC - time by its sampled worker count, then averages. + the Ractor that initiated it, not under `major`. The absolute GC tables + (single-executable reports and the `GC per ruby` table) also show + `GC ms/worker`, which divides each iteration's worker-sum GC time by its + sampled worker count, then averages. * `controller compacts/iter*` 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/harness.rb b/harness-gc/harness.rb index ab627e1f..fec2e6b3 100644 --- a/harness-gc/harness.rb +++ b/harness-gc/harness.rb @@ -148,8 +148,9 @@ def run_benchmark(_num_itrs_hint, **, &block) heap_snapshot.each do |idx, stats| slot_size = stats[:slot_size] || 0 eden_slots = stats[:heap_eden_slots] || 0 - live_slots = stats[:heap_live_slots] || 0 - free_slots = stats[:heap_free_slots] || 0 + # Ruby < 4.0 omits heap_live_slots/heap_free_slots; derive them from the per-heap counters. + live_slots = stats[:heap_live_slots] || stats[:total_allocated_objects].to_i - stats[:total_freed_objects].to_i + free_slots = stats[:heap_free_slots] || eden_slots - live_slots eden_pages = stats[:heap_eden_pages] || 0 live_pct = eden_slots > 0 ? (live_slots * 100.0 / eden_slots) : 0.0 mem_kib = page_size ? (eden_pages * page_size / 1024.0) : 0.0 diff --git a/lib/benchmark_runner.rb b/lib/benchmark_runner.rb index 38f9222e..6fa0f67b 100644 --- a/lib/benchmark_runner.rb +++ b/lib/benchmark_runner.rb @@ -65,6 +65,10 @@ def build_output_text(ruby_descriptions, table, format, bench_failures, include_ output_str << "#{title}:\n" if title output_str << TableFormatter.new(section[:table], section[:format], section.fetch(:failures, {})).to_s + "\n" + if section[:include_gc] && section[:gc_per_ruby_table] && section[:gc_per_ruby_format] + output_str << (title ? "GC per ruby (#{title}):\n" : "GC per ruby:\n") + output_str << TableFormatter.new(section[:gc_per_ruby_table], section[:gc_per_ruby_format], {}).to_s + "\n" + end if section[:include_gc] && section[:gc_table] && section[:gc_format] output_str << (title ? "GC summary (#{title}):\n" : "GC summary:\n") output_str << TableFormatter.new(section[:gc_table], section[:gc_format], {}).to_s + "\n" @@ -81,25 +85,32 @@ def build_output_text(ruby_descriptions, table, format, bench_failures, include_ end end if has_gc_summary + if sections.any? { |section| section[:include_gc] && section[:gc_per_ruby_table] } + output_str << "- GC per ruby shows the mean GC values per benchmark iteration for each ruby. These values are not ratios. Benchmarks with no GC activity on any ruby are omitted.\n" + end output_str << "- GC summary compares #{base_name} → comparison. Ratio columns are #{base_name}/comparison; above 1 means the comparison spent less GC time.\n" output_str << "- gc/iter, mark/iter, and sweep/iter ratio 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 ratio 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" - output_str << "- GCs/iter, major/iter, minor/iter, controller compacts/iter*, and minor GC % show #{base_name} → comparison values, not ratios. Rows with no GC activity are omitted.\n" + output_str << "- In GC summary, GCs/iter, major/iter, minor/iter, controller compacts/iter*, and minor GC % show #{base_name} → comparison values, not ratios. A row is omitted when neither #{base_name} nor the comparison has GC activity.\n" end if include_pvalue output_str << "- ***: p < 0.001, **: p < 0.01, *: p < 0.05 (Welch's t-test)\n" end end - gc_headers = sections.filter_map { |section| section[:gc_table]&.first }.flatten + gc_headers = sections.flat_map { |section| [section[:gc_table]&.first, section[:gc_per_ruby_table]&.first] }.compact.flatten + per_ruby_headers = sections.filter_map { |section| section[:gc_per_ruby_table]&.first }.flatten if gc_headers.include?('controller compacts/iter*') output_str << "GC metric notes:\n" - output_str << "- controller compacts/iter*: the main Ractor's GC.stat(:compact_count) delta per iteration. Every global compacting cycle increments compact_count in every object space. Do not sum it across workers.#{other_names.empty? ? '' : " Comparison tables show #{base_name} → comparison values."}\n" + compaction_note = +"" + compaction_note << " GC summary shows #{base_name} → comparison values." unless other_names.empty? + compaction_note << " GC per ruby shows the value for each ruby." if per_ruby_headers.include?('controller compacts/iter*') + output_str << "- controller compacts/iter*: the main Ractor's GC.stat(:compact_count) delta per iteration. Every global compacting cycle increments compact_count in every object space. Do not sum it across workers.#{compaction_note}\n" end if sections.any? { |section| section[:gc_scope] == 'ractor-local-workload' && section[:gc_table] } output_str << "Ractor GC scope note:\n" scope_columns = +"- (worker sum) columns add Ractor-local counters across the sampled workers of each iteration; the main Ractor performs the count-0 workload." - scope_columns << " GC ms/worker divides each iteration's worker-sum GC time by its sampled worker count, then averages." if other_names.empty? + scope_columns << " GC ms/worker divides each iteration's worker-sum GC time by its sampled worker count, then averages." if gc_headers.include?('GC ms/worker') output_str << "#{scope_columns} Controller snapshots and per-worker heap detail are in the JSON output, not this table.\n" output_str << "- Ruby's Ractor-retirement GC (after a worker's stack is torn down) and Ractors created by the workload itself are not sampled.\n" output_str << "- GC time is CPU-time accounting, not elapsed pause time; summed across Ractors it can exceed wall time.\n" diff --git a/lib/benchmark_runner/cli.rb b/lib/benchmark_runner/cli.rb index ed59d2d1..1a59b0c2 100644 --- a/lib/benchmark_runner/cli.rb +++ b/lib/benchmark_runner/cli.rb @@ -194,6 +194,7 @@ def build_output_section(executable_names, bench_data, bench_failures, harness, row_layout: layout ) table, format, gc_table, gc_format = builder.build + gc_per_ruby_table, gc_per_ruby_format = builder.build_gc_per_ruby section = { title: harness, @@ -203,6 +204,8 @@ def build_output_section(executable_names, bench_data, bench_failures, harness, include_gc: builder.include_gc?, gc_table: gc_table, gc_format: gc_format, + gc_per_ruby_table: gc_per_ruby_table, + gc_per_ruby_format: gc_per_ruby_format, } section[:gc_scope] = 'ractor-local-workload' if ResultsTableBuilder.ractor_gc_data?(section_data) section diff --git a/lib/results_table_builder.rb b/lib/results_table_builder.rb index 8450331d..d8b52b3c 100644 --- a/lib/results_table_builder.rb +++ b/lib/results_table_builder.rb @@ -47,6 +47,13 @@ def build [table, format, gc_table, build_gc_summary_format(gc_table)] end + def build_gc_per_ruby + return [nil, nil] unless @include_gc && !@other_names.empty? + + table = build_gc_absolute_table(["bench", *@row_layout.extra_header_columns], @executable_names) + [table, build_gc_summary_format(table)] + end + private def has_complete_data?(bench_name) @@ -128,7 +135,7 @@ def build_gc_summary_table label_columns = ["bench", *@row_layout.extra_header_columns] if @other_names.empty? - return build_gc_absolute_table(label_columns) + return build_gc_absolute_table(label_columns, [@base_name]) end count_suffix = ractor_gc_table? ? " (worker sum)" : "" @@ -168,11 +175,12 @@ def build_gc_summary_table rows.size == 1 ? nil : rows end - def build_gc_absolute_table(label_columns) + def build_gc_absolute_table(label_columns, names) ractor = ractor_gc_table? count_suffix = ractor ? " (worker sum)" : "" + per_ruby = names.size > 1 - header = label_columns + ["GC ms/iter#{count_suffix}"] + header = label_columns + (per_ruby ? ["ruby"] : []) + ["GC ms/iter#{count_suffix}"] header << "GC ms/worker" if ractor header += ["mark ms/iter#{count_suffix}", "sweep ms/iter#{count_suffix}", "GCs/iter#{count_suffix}", "major/iter#{count_suffix}", "minor/iter#{count_suffix}"] header << "global/iter#{count_suffix}" if gc_series_present?('gc_global_count_bench') @@ -181,21 +189,25 @@ def build_gc_absolute_table(label_columns) rows = [header] gc_entries.each do |entry| - data = bench_data_for(@base_name, entry.data_key) - next unless GC_SERIES_KEYS.any? { |key| data.key?(key) } - - cells = [format_gc_series_mean_precise(data['gc_total_time_bench'])] - cells << gc_ms_per_worker_cell(data['gc_total_time_bench'], data['gc_worker_samples']) if ractor - cells += [ - format_gc_series_mean_precise(data['gc_marking_time_bench']), - format_gc_series_mean_precise(data['gc_sweeping_time_bench']), - format_gc_series_mean(gc_count_series(data)), - format_gc_series_mean(data['gc_major_count_bench']), - format_gc_series_mean(data['gc_minor_count_bench']), - ] - cells << format_gc_series_mean(data['gc_global_count_bench']) if gc_series_present?('gc_global_count_bench') - cells << format_gc_series_mean(data['gc_controller_compact_count_bench']) if gc_series_present?('gc_controller_compact_count_bench') - rows << gc_label_cells(entry) + cells + data_by_name = names.to_h { |name| [name, bench_data_for(name, entry.data_key)] } + next if per_ruby && !gc_activity?(*data_by_name.values.flat_map { |data| data.values_at(*GC_SERIES_KEYS) }) + + data_by_name.each do |name, data| + next unless GC_SERIES_KEYS.any? { |key| data.key?(key) } + + cells = [format_gc_series_mean_precise(data['gc_total_time_bench'])] + cells << gc_ms_per_worker_cell(data['gc_total_time_bench'], data['gc_worker_samples']) if ractor + cells += [ + format_gc_series_mean_precise(data['gc_marking_time_bench']), + format_gc_series_mean_precise(data['gc_sweeping_time_bench']), + format_gc_series_mean(gc_count_series(data)), + format_gc_series_mean(data['gc_major_count_bench']), + format_gc_series_mean(data['gc_minor_count_bench']), + ] + cells << format_gc_series_mean(data['gc_global_count_bench']) if gc_series_present?('gc_global_count_bench') + cells << format_gc_series_mean(data['gc_controller_compact_count_bench']) if gc_series_present?('gc_controller_compact_count_bench') + rows << gc_label_cells(entry) + (per_ruby ? [name] : []) + cells + end end rows.size == 1 ? nil : rows diff --git a/test/benchmark_runner_test.rb b/test/benchmark_runner_test.rb index 7792d8b5..886a0298 100644 --- a/test/benchmark_runner_test.rb +++ b/test/benchmark_runner_test.rb @@ -461,7 +461,8 @@ assert_includes result, "- controller compacts/iter*: the main Ractor's GC.stat(:compact_count) delta per iteration." assert_includes result, 'Every global compacting cycle increments compact_count in every object space.' assert_includes result, 'Do not sum it across workers.' - assert_includes result, 'Comparison tables show ruby-base → comparison values.' + assert_includes result, 'GC summary shows ruby-base → comparison values.' + refute_includes result, 'GC per ruby shows the value for each ruby.' refute_includes result, 'global GCs/iter' end @@ -482,7 +483,7 @@ refute_includes result, 'Legend:' assert_includes result, "GC metric notes:\n" assert_includes result, "- controller compacts/iter*: the main Ractor's GC.stat(:compact_count) delta per iteration." - refute_includes result, 'Comparison tables show' + refute_includes result, 'GC summary shows' refute_includes result, 'global GCs/iter' end @@ -508,7 +509,7 @@ refute_includes result, 'GC metric notes:' assert_includes result, "the same run's GCs/iter count" - assert_includes result, 'show ruby-base → comparison values, not ratios' + assert_includes result, 'In GC summary, GCs/iter, major/iter, minor/iter, controller compacts/iter*, and minor GC % show ruby-base → comparison values, not ratios. A row is omitted when neither ruby-base nor the comparison has GC activity.' end it 'omits the Ractor scope note when the section rendered no GC table' do @@ -532,6 +533,74 @@ refute_includes result, 'Ractor GC scope note:' end + it 'prints the GC per ruby table before the GC summary, with its legend line' do + ruby_descriptions = { 'master' => 'ruby 4.1.0dev', 'four' => 'ruby 4.0.6', 'three' => 'ruby 3.4.10' } + sections = [ + { + title: 'harness-gc', + table: [['bench', 'master (ms)', 'four (ms)', 'three (ms)'], ['gcbench', '1.0', '2.0', '3.0']], + format: ['%s', '%s', '%s', '%s'], + failures: {}, + include_gc: true, + gc_per_ruby_table: [ + ['bench', 'ruby', 'GC ms/iter', 'controller compacts/iter*'], + ['gcbench', 'master', '1.000', '0.0'], + ['gcbench', 'four', '2.000', '0.0'], + ['gcbench', 'three', '3.000', '0.0'] + ], + gc_per_ruby_format: ['%s', '%s', '%s', '%s'], + gc_table: [['bench', 'comparison', 'gc/iter ratio'], ['gcbench', 'four', '0.500'], ['gcbench', 'three', '0.333']], + gc_format: ['%s', '%s', '%s'], + }, + { + title: 'harness', + table: [['bench', 'master (ms)', 'four (ms)', 'three (ms)'], ['fib', '1.0', '2.0', '3.0']], + format: ['%s', '%s', '%s', '%s'], + failures: {}, + include_gc: false, + } + ] + + result = BenchmarkRunner.build_output_text( + ruby_descriptions, sections.first[:table], sections.first[:format], {}, sections: sections + ) + + per_ruby_at = result.index("GC per ruby (harness-gc):\n") + summary_at = result.index("GC summary (harness-gc):\n") + refute_nil per_ruby_at + refute_nil summary_at + assert_operator per_ruby_at, :<, summary_at + assert_match(/^gcbench\s+master\s+1\.000\s+0\.0$/, result) + assert_includes result, '- GC per ruby shows the mean GC values per benchmark iteration for each ruby. These values are not ratios. Benchmarks with no GC activity on any ruby are omitted.' + assert_includes result, 'Do not sum it across workers. GC summary shows master → comparison values. GC per ruby shows the value for each ruby.' + refute_includes result, 'GC per ruby (harness):' + end + + it 'explains GC ms/worker in the Ractor scope note when only the GC per ruby table shows it' do + ruby_descriptions = { 'base' => 'ruby 4.1.0dev', 'exp' => 'ruby 4.1.0dev experiment' } + sections = [ + { + title: 'harness-ractor', + table: [['bench', 'ractors', 'base (ms)', 'exp (ms)'], ['object-new', '2', '1.0', '2.0']], + format: ['%s', '%s', '%s', '%s'], + failures: {}, + include_gc: true, + gc_per_ruby_table: [['bench', 'ractors', 'ruby', 'GC ms/iter (worker sum)', 'GC ms/worker'], ['object-new', '2', 'base', '4.000', '2.000']], + gc_per_ruby_format: ['%s'] * 5, + gc_table: [['bench', 'ractors', 'gc/iter ratio'], ['object-new', '2', '2.000']], + gc_format: ['%s'] * 3, + gc_scope: 'ractor-local-workload', + } + ] + + result = BenchmarkRunner.build_output_text( + ruby_descriptions, sections.first[:table], sections.first[:format], {}, sections: sections + ) + + assert_includes result, "Ractor GC scope note:\n" + assert_includes result, "GC ms/worker divides each iteration's worker-sum GC time by its sampled worker count, then averages." + end + it 'includes RSS ratio legend when include_rss is true' do ruby_descriptions = { 'ruby-base' => 'ruby 3.3.0', diff --git a/test/results_table_builder_test.rb b/test/results_table_builder_test.rb index 97246775..bddd5933 100644 --- a/test/results_table_builder_test.rb +++ b/test/results_table_builder_test.rb @@ -714,6 +714,66 @@ assert_equal ['%s'] * 9, gc_format assert_equal ['gcbench', '5.000', '2.000', '1.000', '11.0', '2.0', '8.0', '1.0', '0.0'], gc_table[1] end + + it 'gives every executable, including the baseline, its own row in the GC per ruby table' do + gc_data = ->(mark, major, minor) do + { + 'warmup' => [0.1], + 'bench' => [0.1, 0.1], + 'rss' => 10, + 'gc_marking_time_bench' => [mark, mark], + 'gc_sweeping_time_bench' => [1.0, 1.0], + 'gc_major_count_bench' => [major, major], + 'gc_minor_count_bench' => [minor, minor] + } + end + bench_data = { + 'master' => { 'gcbench' => gc_data.(4.0, 1, 9) }, + 'four' => { 'gcbench' => gc_data.(2.0, 0, 6) }, + 'three' => { 'gcbench' => gc_data.(3.0, 2, 4) } + } + + builder = ResultsTableBuilder.new( + executable_names: ['master', 'four', 'three'], + bench_data: bench_data + ) + + gc_table, gc_format = builder.build_gc_per_ruby + + assert_equal [ + 'bench', 'ruby', 'GC ms/iter', 'mark ms/iter', 'sweep ms/iter', 'GCs/iter', 'major/iter', 'minor/iter' + ], gc_table[0] + assert_equal ['%s'] * 8, gc_format + assert_equal [ + ['gcbench', 'master', 'N/A', '4.000', '1.000', '10.0', '1.0', '9.0'], + ['gcbench', 'four', 'N/A', '2.000', '1.000', '6.0', '0.0', '6.0'], + ['gcbench', 'three', 'N/A', '3.000', '1.000', '6.0', '2.0', '4.0'] + ], gc_table[1..] + end + + it 'omits the GC per ruby table for one executable or idle benchmarks, and keeps idle rubies when another is active' do + idle = { + 'warmup' => [0.1], + 'bench' => [0.1], + 'rss' => 10, + 'gc_marking_time_bench' => [0.0], + 'gc_sweeping_time_bench' => [0.0], + 'gc_major_count_bench' => [0], + 'gc_minor_count_bench' => [0] + } + + single = ResultsTableBuilder.new(executable_names: ['ruby'], bench_data: { 'ruby' => { 'fib' => idle.merge('gc_minor_count_bench' => [3]) } }) + assert_equal [nil, nil], single.build_gc_per_ruby + + multi = ResultsTableBuilder.new(executable_names: ['a', 'b'], bench_data: { 'a' => { 'fib' => idle }, 'b' => { 'fib' => idle } }) + assert_equal [nil, nil], multi.build_gc_per_ruby + + mixed = ResultsTableBuilder.new(executable_names: ['a', 'b'], bench_data: { 'a' => { 'fib' => idle }, 'b' => { 'fib' => idle.merge('gc_minor_count_bench' => [3]) } }) + assert_equal [ + ['fib', 'a', 'N/A', '0.000', '0.000', '0.0', '0.0', '0.0'], + ['fib', 'b', 'N/A', '0.000', '0.000', '3.0', '0.0', '3.0'] + ], mixed.build_gc_per_ruby[0][1..], 'an idle ruby keeps its row when another ruby has GC activity' + end end describe 'RSS sampling (rss_samples)' do @@ -1115,5 +1175,28 @@ def build_ractor_gc(bench_data) ], gc_table[0] assert_equal ['object-new', '0', '4.000', '4.000', 'N/A', 'N/A', '7.0', '1.0', '3.0', '3.0', '1.0'], gc_table[1] end + + it 'puts the ruby column after ractors in the GC per ruby table' do + bench_data = { + 'base' => { 'object-new' => ractor_gc_blob('2' => { bench: [1.0, 1.0], gc: gc_group(total: [12.0, 12.0], major: [2, 2], minor: [6, 6]) }) }, + 'candidate' => { 'object-new' => ractor_gc_blob('2' => { bench: [1.0, 1.0], gc: gc_group(total: [3.0, 3.0], major: [1, 1], minor: [3, 3]) }) } + } + expanded = RactorBreakdown.expand(bench_data) + builder = ResultsTableBuilder.new( + executable_names: bench_data.keys, + bench_data: expanded.bench_data, + row_layout: RactorRowLayout.new(groups: expanded.groups) + ) + + gc_table, gc_format = builder.build_gc_per_ruby + + assert_equal [ + 'bench', 'ractors', 'ruby', 'GC ms/iter (worker sum)', 'GC ms/worker', 'mark ms/iter (worker sum)', + 'sweep ms/iter (worker sum)', 'GCs/iter (worker sum)', 'major/iter (worker sum)', 'minor/iter (worker sum)' + ], gc_table[0] + assert_equal ['%s'] * 10, gc_format + assert_equal ['object-new', '2', 'base', '12.000', '12.000', 'N/A', 'N/A', '8.0', '2.0', '6.0'], gc_table[1] + assert_equal ['object-new', '2', 'candidate', '3.000', '3.000', 'N/A', 'N/A', '4.0', '1.0', '3.0'], gc_table[2] + end end end