Skip to content

Commit 6364711

Browse files
Split the GC summary into ratio and count tables
With Ractor GC data, the comparison GC summary was over 250 characters wide. This commit splits it into a GC time ratios table and a GC counts table. The "ratio" and "worker sum" labels move out of the column headers and into the table titles. Columns with no data in any row are hidden and listed under the table. global/iter is now shown as a count instead of a ratio. It's a GC count, and the legend says the ratios are GC time.
1 parent de8b5fd commit 6364711

7 files changed

Lines changed: 366 additions & 218 deletions

File tree

‎README.md‎

Lines changed: 11 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -411,15 +411,21 @@ Ractor's own object space. The JSON output records the scope as
411411
`gc_scope: "ractor-local-workload"`, `gc_stat_scope: "ractor-local"`, and
412412
`gc_measure_total_time_scope: "ractor-local"`, plus the target's `gc_config`.
413413

414-
The summary table adds these columns:
415-
416-
* `(worker sum)` columns add the Ractor-local counters of the sampled
417-
workers of each iteration. `GCs/iter` is the sum of `minor/iter`,
414+
The text summary shows GC data in separate tables after the timing table.
415+
A single-executable report has one `GC summary` table. A comparison report
416+
has a `GC time ratios` table (base/comparison) and a `GC counts` table
417+
(base → comparison). A table hides a column that has no data in any row and
418+
lists the hidden columns below the table. A ratio column has no data when it
419+
is `N/A` in every row; a `0.000` ratio stays visible. Any other column has no
420+
data when it is zero or `N/A` in every row.
421+
422+
* Tables marked `worker sum` add the Ractor-local counters and GC times of
423+
the sampled workers of each iteration. `GCs/iter` is the sum of `minor/iter`,
418424
`major/iter`, and `global/iter`; a global cycle counts under `global` on
419425
the Ractor that initiated it, not under `major`. Single-executable reports
420426
also show `GC ms/worker`, which divides each iteration's worker-sum GC
421427
time by its sampled worker count, then averages.
422-
* `controller compacts/iter*` shows the main Ractor's
428+
* `compacts*` shows the main Ractor's
423429
`GC.stat(:compact_count)` delta. Every global compacting cycle increments
424430
it in every object space, so it is not summed across workers.
425431

‎lib/benchmark_runner.rb‎

Lines changed: 23 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -59,7 +59,7 @@ def write_csv(output_path, ruby_descriptions, table)
5959
end
6060

6161
# Build output text string with metadata, table, and legend
62-
def build_output_text(ruby_descriptions, table, format, bench_failures, include_rss: false, include_gc: false, include_pvalue: false, gc_table: nil, gc_format: nil, sections: nil, ruby_bench_revision: nil)
62+
def build_output_text(ruby_descriptions, table, format, bench_failures, include_rss: false, include_gc: false, include_pvalue: false, gc_tables: nil, sections: nil, ruby_bench_revision: nil)
6363
base_name, *other_names = ruby_descriptions.keys
6464

6565
output_str = +""
@@ -70,16 +70,23 @@ def build_output_text(ruby_descriptions, table, format, bench_failures, include_
7070
output_str << "ruby-bench: #{ruby_bench_revision}\n" if ruby_bench_revision
7171

7272
output_str << "\n"
73-
sections ||= [{ table: table, format: format, failures: bench_failures, include_gc: include_gc, gc_table: gc_table, gc_format: gc_format }]
74-
has_gc_summary = sections.any? { |section| section[:include_gc] && section[:gc_table] }
73+
sections ||= [{ table: table, format: format, failures: bench_failures, include_gc: include_gc, gc_tables: gc_tables }]
74+
has_gc_summary = sections.any? { |section| section[:include_gc] && section[:gc_tables] }
7575
sections.each do |section|
7676
title = section[:title]
7777
output_str << "#{title}:\n" if title
7878
output_str << TableFormatter.new(section[:table], section[:format], section.fetch(:failures, {})).to_s + "\n"
7979

80-
if section[:include_gc] && section[:gc_table] && section[:gc_format]
81-
output_str << (title ? "GC summary (#{title}):\n" : "GC summary:\n")
82-
output_str << TableFormatter.new(section[:gc_table], section[:gc_format], {}).to_s + "\n"
80+
next unless section[:include_gc] && section[:gc_tables]
81+
82+
section[:gc_tables].each do |gc_table|
83+
qualifiers = [gc_table[:scope], title].compact
84+
output_str << gc_table[:name]
85+
output_str << " (#{qualifiers.join(', ')})" unless qualifiers.empty?
86+
output_str << ":\n"
87+
output_str << TableFormatter.new(gc_table[:rows], Array.new(gc_table[:rows].first.size, "%s"), {}).to_s
88+
output_str << "Hidden columns (zero or N/A in every row): #{gc_table[:hidden].join(', ')}\n" unless gc_table[:hidden].empty?
89+
output_str << "\n"
8390
end
8491
end
8592

@@ -93,30 +100,30 @@ def build_output_text(ruby_descriptions, table, format, bench_failures, include_
93100
end
94101
end
95102
if has_gc_summary
96-
output_str << "- GC summary compares #{base_name} → comparison. Ratio columns are #{base_name}/comparison; above 1 means the comparison spent less GC time.\n"
97-
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"
98-
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"
99-
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"
103+
output_str << "- GC time ratios are #{base_name}/comparison; above 1 means the comparison spent less GC time.\n"
104+
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"
105+
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"
106+
output_str << "- GC counts show #{base_name} → comparison values, not ratios. Rows with no GC activity are omitted.\n"
100107
end
101108
if include_pvalue
102109
output_str << "- ***: p < 0.001, **: p < 0.01, *: p < 0.05 (Welch's t-test)\n"
103110
end
104111
end
105-
gc_headers = sections.filter_map { |section| section[:gc_table]&.first }.flatten
106-
if gc_headers.include?('controller compacts/iter*')
112+
gc_headers = sections.flat_map { |section| Array(section[:gc_tables]).flat_map { |gc_table| gc_table[:rows].first } }
113+
if gc_headers.include?('compacts*')
107114
output_str << "GC metric notes:\n"
108-
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"
115+
output_str << "- compacts*: 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"
109116
end
110117

111-
ractor_gc_sections = sections.select { |section| section[:gc_scope] == 'ractor-local-workload' && section[:gc_table] }
118+
ractor_gc_sections = sections.select { |section| section[:gc_scope] == 'ractor-local-workload' && section[:gc_tables] }
112119
unless ractor_gc_sections.empty?
113120
modes = ractor_gc_sections.flat_map { |section| section.fetch(:ractor_gc_modes, []) }
114121
worker_mode = modes.include?(:worker)
115122
output_str << "Ractor GC scope note:\n"
116-
scope_columns = +"- (worker sum) columns add Ractor-local counters across the sampled workers of each iteration"
123+
scope_columns = +"- Tables marked worker sum add Ractor-local counters and GC times across the sampled workers of each iteration"
117124
scope_columns << (worker_mode ? "; the main Ractor performs the count-0 workload of per-worker benchmarks." : ".")
118125
scope_columns << " GC ms/worker divides each iteration's worker-sum GC time by its sampled worker count, then averages." if other_names.empty?
119-
output_str << "#{scope_columns} Controller snapshots and per-worker heap detail are in the JSON output, not this table.\n"
126+
output_str << "#{scope_columns} Controller snapshots and per-worker heap detail are in the JSON output, not these tables.\n"
120127
output_str << "- Ruby's Ractor-retirement GC (after a worker's stack is torn down) is not sampled."
121128
output_str << " Ractors created by the workload of a per-worker benchmark are not sampled." if worker_mode
122129
output_str << "\n"

‎lib/benchmark_runner/cli.rb‎

Lines changed: 4 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -125,7 +125,7 @@ def run
125125
zjit_stats: args.zjit_stats,
126126
row_layout: csv_layout
127127
)
128-
table, format, gc_table, gc_format = builder.build
128+
table, format, gc_tables = builder.build
129129

130130
output_path = BenchmarkRunner.output_path(args.out_path, out_override: args.out_override)
131131

@@ -139,7 +139,7 @@ def run
139139

140140
# Save the output in a text file that we can easily refer to
141141
output_sections = build_output_sections(ruby_descriptions.keys, bench_data, bench_harnesses, bench_failures)
142-
output_str = BenchmarkRunner.build_output_text(ruby_descriptions, table, format, bench_failures, include_rss: args.rss, include_gc: builder.include_gc?, include_pvalue: args.pvalue, gc_table: gc_table, gc_format: gc_format, sections: output_sections, ruby_bench_revision: ruby_bench_revision)
142+
output_str = BenchmarkRunner.build_output_text(ruby_descriptions, table, format, bench_failures, include_rss: args.rss, include_gc: builder.include_gc?, include_pvalue: args.pvalue, gc_tables: gc_tables, sections: output_sections, ruby_bench_revision: ruby_bench_revision)
143143
out_txt_path = output_path + ".txt"
144144
File.open(out_txt_path, "w") { |f| f.write output_str }
145145

@@ -208,16 +208,15 @@ def build_output_section(executable_names, bench_data, bench_failures, harness,
208208
zjit_stats: args.zjit_stats,
209209
row_layout: layout
210210
)
211-
table, format, gc_table, gc_format = builder.build
211+
table, format, gc_tables = builder.build
212212

213213
section = {
214214
title: harness,
215215
table: table,
216216
format: format,
217217
failures: slice_failures(bench_failures, bench_names),
218218
include_gc: builder.include_gc?,
219-
gc_table: gc_table,
220-
gc_format: gc_format,
219+
gc_tables: gc_tables,
221220
}
222221
if ResultsTableBuilder.ractor_gc_data?(section_data)
223222
section[:gc_scope] = 'ractor-local-workload'

‎lib/results_table_builder.rb‎

Lines changed: 111 additions & 73 deletions
Original file line numberDiff line numberDiff line change
@@ -42,9 +42,7 @@ def build
4242
table << (entry.label_cells + build_stat_cells(entry.data_key))
4343
end
4444

45-
gc_table = build_gc_summary_table
46-
47-
[table, format, gc_table, build_gc_summary_format(gc_table)]
45+
[table, format, build_gc_tables]
4846
end
4947

5048
private
@@ -122,26 +120,18 @@ def build_format
122120
gc_controller_compact_count_bench
123121
].freeze
124122

125-
def build_gc_summary_table
123+
def build_gc_tables
126124
return nil unless @include_gc
127125

128-
label_columns = ["bench", *@row_layout.extra_header_columns]
129-
130-
if @other_names.empty?
131-
return build_gc_absolute_table(label_columns)
132-
end
133-
134-
count_suffix = ractor_gc_table? ? " (worker sum)" : ""
135-
136-
header = label_columns + (include_gc_comparison_name? ? ["comparison"] : [])
137-
header += ["gc/iter ratio", "gc/GC ratio"] if include_gc_total_time?
138-
header += ["mark/iter ratio", "sweep/iter ratio", "mark/GC ratio", "sweep/GC ratio"]
139-
header << "global/iter ratio" if gc_series_present?('gc_global_count_bench')
140-
header << "GCs/iter#{count_suffix}" << "major/iter#{count_suffix}" << "minor/iter#{count_suffix}"
141-
header << "controller compacts/iter*" if gc_series_present?('gc_controller_compact_count_bench')
142-
header << "minor GC %"
126+
label_header = ["bench", *@row_layout.extra_header_columns]
127+
tables = @other_names.empty? ? [build_gc_absolute_table(label_header)] : build_gc_comparison_tables(label_header)
128+
tables.compact!
129+
tables.empty? ? nil : tables
130+
end
143131

144-
rows = [header]
132+
def build_gc_comparison_tables(label_header)
133+
label_header += ["comparison"] if include_gc_comparison_name?
134+
rows = []
145135
gc_entries.each do |entry|
146136
series_by_exe = @executable_names.map do |name|
147137
data = bench_data_for(name, entry.data_key)
@@ -161,44 +151,118 @@ def build_gc_summary_table
161151
others.each_with_index do |other, i|
162152
next unless gc_activity?(*base.values, *other.values)
163153

164-
rows << gc_summary_row(gc_label_cells(entry), @other_names[i], base, other)
154+
labels = gc_label_cells(entry)
155+
labels << @other_names[i] if include_gc_comparison_name?
156+
rows << [labels, [base, other]]
165157
end
166158
end
167159

168-
rows.size == 1 ? nil : rows
160+
[
161+
assemble_gc_table("GC time ratios", label_header, rows, gc_ratio_columns),
162+
assemble_gc_table("GC counts", label_header, rows, gc_count_columns),
163+
]
169164
end
170165

171-
def build_gc_absolute_table(label_columns)
172-
ractor = ractor_gc_table?
173-
count_suffix = ractor ? " (worker sum)" : ""
174-
175-
header = label_columns + ["GC ms/iter#{count_suffix}"]
176-
header << "GC ms/worker" if ractor
177-
header += ["mark ms/iter#{count_suffix}", "sweep ms/iter#{count_suffix}", "GCs/iter#{count_suffix}", "major/iter#{count_suffix}", "minor/iter#{count_suffix}"]
178-
header << "global/iter#{count_suffix}" if gc_series_present?('gc_global_count_bench')
179-
header << "controller compacts/iter*" if gc_series_present?('gc_controller_compact_count_bench')
166+
def gc_ratio_columns
167+
columns = []
168+
if include_gc_total_time?
169+
columns << ["gc/iter", ->(base, other) { ratio_cell(gc_ratio(base[:total], other[:total])) }]
170+
columns << ["gc/GC", ->(base, other) { ratio_cell(per_gc_ratio(base, other, :total)) }]
171+
end
172+
columns << ["mark/iter", ->(base, other) { ratio_cell(gc_ratio(base[:mark], other[:mark])) }]
173+
columns << ["sweep/iter", ->(base, other) { ratio_cell(gc_ratio(base[:sweep], other[:sweep])) }]
174+
columns << ["mark/GC", ->(base, other) { ratio_cell(per_gc_ratio(base, other, :mark)) }]
175+
columns << ["sweep/GC", ->(base, other) { ratio_cell(per_gc_ratio(base, other, :sweep)) }]
176+
columns
177+
end
180178

181-
rows = [header]
179+
def gc_count_columns
180+
columns = [
181+
["GCs/iter", ->(base, other) { count_cell(base[:count], other[:count]) }],
182+
["major/iter", ->(base, other) { count_cell(base[:major], other[:major]) }],
183+
["minor/iter", ->(base, other) { count_cell(base[:minor], other[:minor]) }],
184+
]
185+
if gc_series_present?('gc_global_count_bench')
186+
columns << ["global/iter", ->(base, other) { count_cell(base[:global], other[:global]) }]
187+
end
188+
if gc_series_present?('gc_controller_compact_count_bench')
189+
columns << ["compacts*", ->(base, other) { count_cell(base[:compact], other[:compact]) }]
190+
end
191+
columns << ["minor GC %", ->(base, other) { minor_percent_cell(base, other) }]
192+
columns
193+
end
182194

183-
gc_entries.each do |entry|
195+
def build_gc_absolute_table(label_header)
196+
rows = gc_entries.filter_map do |entry|
184197
data = bench_data_for(@base_name, entry.data_key)
185-
next unless GC_SERIES_KEYS.any? { |key| data.key?(key) }
198+
[gc_label_cells(entry), [data]] if GC_SERIES_KEYS.any? { |key| data.key?(key) }
199+
end
200+
assemble_gc_table("GC summary", label_header, rows, gc_absolute_columns)
201+
end
186202

187-
cells = [format_gc_series_mean_precise(data['gc_total_time_bench'])]
188-
cells << gc_ms_per_worker_cell(data['gc_total_time_bench'], data['gc_worker_samples']) if ractor
189-
cells += [
190-
format_gc_series_mean_precise(data['gc_marking_time_bench']),
191-
format_gc_series_mean_precise(data['gc_sweeping_time_bench']),
192-
format_gc_series_mean(gc_count_series(data)),
193-
format_gc_series_mean(data['gc_major_count_bench']),
194-
format_gc_series_mean(data['gc_minor_count_bench']),
195-
]
196-
cells << format_gc_series_mean(data['gc_global_count_bench']) if gc_series_present?('gc_global_count_bench')
197-
cells << format_gc_series_mean(data['gc_controller_compact_count_bench']) if gc_series_present?('gc_controller_compact_count_bench')
198-
rows << gc_label_cells(entry) + cells
203+
def gc_absolute_columns
204+
columns = [["GC ms/iter", ->(data) { mean_cell(data['gc_total_time_bench'], precise: true) }]]
205+
columns << ["GC ms/worker", ->(data) { ms_per_worker_cell(data) }] if ractor_gc_table?
206+
columns += [
207+
["mark ms/iter", ->(data) { mean_cell(data['gc_marking_time_bench'], precise: true) }],
208+
["sweep ms/iter", ->(data) { mean_cell(data['gc_sweeping_time_bench'], precise: true) }],
209+
["GCs/iter", ->(data) { mean_cell(gc_count_series(data)) }],
210+
["major/iter", ->(data) { mean_cell(data['gc_major_count_bench']) }],
211+
["minor/iter", ->(data) { mean_cell(data['gc_minor_count_bench']) }],
212+
]
213+
if gc_series_present?('gc_global_count_bench')
214+
columns << ["global/iter", ->(data) { mean_cell(data['gc_global_count_bench']) }]
215+
end
216+
if gc_series_present?('gc_controller_compact_count_bench')
217+
columns << ["compacts*", ->(data) { mean_cell(data['gc_controller_compact_count_bench']) }]
199218
end
219+
columns
220+
end
221+
222+
def assemble_gc_table(name, label_header, rows, columns)
223+
return nil if rows.empty?
200224

201-
rows.size == 1 ? nil : rows
225+
cells = rows.map { |(_labels, args)| columns.map { |(_header, cell)| cell.call(*args) } }
226+
shown = columns.each_index.select { |i| cells.any? { |row_cells| row_cells[i][1] } }
227+
228+
body = rows.each_with_index.map { |(labels, _args), r| labels + shown.map { |i| cells[r][i][0] } }
229+
{
230+
name: name,
231+
scope: ractor_gc_table? ? "worker sum" : nil,
232+
rows: [label_header + shown.map { |i| columns[i][0] }] + body,
233+
hidden: (columns.each_index.to_a - shown).map { |i| columns[i][0] },
234+
}
235+
end
236+
237+
def ratio_cell(text)
238+
[text, text != "N/A"]
239+
end
240+
241+
def count_cell(base, other)
242+
[gc_count_cell(base, other), mean_positive?(base) || mean_positive?(other)]
243+
end
244+
245+
def minor_percent_cell(base, other)
246+
data = [gc_minor_percent(base[:minor], base[:count]), gc_minor_percent(other[:minor], other[:count])].any? { |pct| pct&.positive? }
247+
[gc_minor_percent_cell(base, other), data]
248+
end
249+
250+
def mean_cell(values, precise: false)
251+
text = precise ? format_gc_series_mean_precise(values) : format_gc_series_mean(values)
252+
[text, mean_positive?(values)]
253+
end
254+
255+
def ms_per_worker_cell(data)
256+
text = gc_ms_per_worker_cell(data['gc_total_time_bench'], data['gc_worker_samples'])
257+
[text, text != "N/A" && mean_positive?(data['gc_total_time_bench'])]
258+
end
259+
260+
def mean_positive?(values)
261+
numeric_series?(values) && mean(values) > 0.0
262+
end
263+
264+
def per_gc_ratio(base, other, key)
265+
scalar_ratio(gc_time_per_gc(base[key], base[:count]), gc_time_per_gc(other[key], other[:count]))
202266
end
203267

204268
def gc_series_present?(key)
@@ -233,12 +297,6 @@ def include_gc_total_time?
233297
end
234298
end
235299

236-
def build_gc_summary_format(gc_table)
237-
return nil unless gc_table
238-
239-
Array.new(gc_table.first.size, "%s")
240-
end
241-
242300
def build_stat_cells(bench_name)
243301
t0s = extract_first_iteration_times(bench_name)
244302
times_no_warmup = extract_benchmark_times(bench_name)
@@ -316,26 +374,6 @@ def include_gc_comparison_name?
316374
@other_names.size > 1
317375
end
318376

319-
def gc_summary_row(label_cells, name, base, other)
320-
row = label_cells
321-
row << name if include_gc_comparison_name?
322-
if include_gc_total_time?
323-
row << gc_ratio(base[:total], other[:total])
324-
row << scalar_ratio(gc_time_per_gc(base[:total], base[:count]), gc_time_per_gc(other[:total], other[:count]))
325-
end
326-
row << gc_ratio(base[:mark], other[:mark])
327-
row << gc_ratio(base[:sweep], other[:sweep])
328-
row << scalar_ratio(gc_time_per_gc(base[:mark], base[:count]), gc_time_per_gc(other[:mark], other[:count]))
329-
row << scalar_ratio(gc_time_per_gc(base[:sweep], base[:count]), gc_time_per_gc(other[:sweep], other[:count]))
330-
row << gc_ratio(base[:global], other[:global]) if gc_series_present?('gc_global_count_bench')
331-
row << gc_count_cell(base[:count], other[:count])
332-
row << gc_count_cell(base[:major], other[:major])
333-
row << gc_count_cell(base[:minor], other[:minor])
334-
row << gc_count_cell(base[:compact], other[:compact]) if gc_series_present?('gc_controller_compact_count_bench')
335-
row << gc_minor_percent_cell(base, other)
336-
row
337-
end
338-
339377
def numeric_series?(values)
340378
values.is_a?(Array) && !values.empty? && values.all? { |v| v.is_a?(Numeric) }
341379
end

0 commit comments

Comments
 (0)