8000 Merge pull request #111 from Shopify/add_exits_to_yjit_stats · eileencodes/ruby@77654f2 · GitHub
[go: up one dir, main page]
Skip to content

Commit 77654f2

Browse files
maximecbmaximecb
authored
Merge pull request ruby#111 from Shopify/add_exits_to_yjit_stats
Add exits to yjit stats, convert at-exit reporting to Ruby
2 parents e415972 + deaa52e commit 77654f2

File tree

2 files changed

+105
-139
lines changed

2 files changed

+105
-139
lines changed

‎yjit.rb

Lines changed: 73 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -125,7 +125,7 @@ def self.disasm_block(cs, block, highlight)
125125
# Return nil when option is not passed or unavailable.
126126
def self.runtime_stats
127127
# defined in yjit_iface.c
128-
Primitive.get_stat_counters
128+
Primitive.get_yjit_stats
129129
end
130130

131131
# Discard statistics collected for --yjit-stats.
@@ -139,18 +139,78 @@ class << self
139139

140140
# Format and print out counters
141141
def _print_stats
142-
counters = runtime_stats
143-
return unless counters
144-
145-
$stderr.puts("***YJIT: Printing runtime counters from yjit.rb***")
146-
$stderr.puts("Number of bindings allocated: %d\n" % counters[:binding_allocations])
147-
$stderr.puts("Number of locals modified through binding: %d\n" % counters[:binding_set])
148-
149-
print_counters(counters, prefix: 'send_', prompt: 'method call exit reasons: ')
150-
print_counters(counters, prefix: 'leave_', prompt: 'leave exit reasons: ')
151-
print_counters(counters, prefix: 'getivar_', prompt: 'getinstancevariable exit reasons:')
152-
print_counters(counters, prefix: 'setivar_', prompt: 'setinstancevariable exit reasons:')
153-
print_counters(counters, prefix: 'oaref_', prompt: 'opt_aref exit reasons: ')
142+
stats = runtime_stats
143+
return unless stats
144+
145+
$stderr.puts("***YJIT: Printing YJIT statistics on exit***")
146+
$stderr.puts("Number of bindings allocated: %d\n" % stats[:binding_allocations])
147+
$stderr.puts("Number of locals modified through binding: %d\n" % stats[:binding_set])
148+
149+
print_counters(stats, prefix: 'send_', prompt: 'method call exit reasons: ')
150+
print_counters(stats, prefix: 'leave_', prompt: 'leave exit reasons: ')
151+
print_counters(stats, prefix: 'getivar_', prompt: 'getinstancevariable exit reasons:')
152+
print_counters(stats, prefix: 'setivar_', prompt: 'setinstancevariable exit reasons:')
153+
print_counters(stats, prefix: 'oaref_', prompt: 'opt_aref exit reasons: ')
154+
155+
total_exits = total_exit_count(stats)
156+
157+
# Number of instructions that finish executing in YJIT
158+
retired_in_yjit = stats[:exec_instruction] - total_exits
159+
160+
# Average length of instruction sequences executed by YJIT
161+
avg_len_in_yjit = retired_in_yjit.to_f / total_exits
162+
163+
# Proportion of instructions that retire in YJIT
164+
total_insns_count = retired_in_yjit + stats[:vm_insns_count]
165+
yjit_ratio_pct = 100.0 * retired_in_yjit.to_f / total_insns_count
166+
167+
$stderr.puts "compiled_iseq_count: " + ("%10d" % stats[:compiled_iseq_count])
168+
$stderr.puts "inline_code_size: " + ("%10d" % stats[:inline_code_size])
169+
$stderr.puts "outlined_code_size: " + ("%10d" % stats[:outlined_code_size])
170+
171+
$stderr.puts "total_exit_count: " + ("%10d" % total_exits)
172+
$stderr.puts "total_insns_count: " + ("%10d" % total_insns_count)
173+
$stderr.puts "vm_insns_count: " + ("%10d" % stats[:vm_insns_count])
174+
$stderr.puts "yjit_insns_count: " + ("%10d" % stats[:exec_instruction])
175+
$stderr.puts "ratio_in_yjit: " + ("%9.1f" % yjit_ratio_pct) + "%"
176+
$stderr.puts "avg_len_in_yjit: " + ("%10.1f" % avg_len_in_yjit)
177+
178+
print_sorted_exit_counts(stats, prefix: "exit_")
179+
end
180+
181+
def print_sorted_exit_counts(stats, prefix:, how_many: 20, left_pad: 4)
182+
exits = []
183+
stats.each do |k, v|
184+
if k.start_with?(prefix)
185+
exits.push [k.to_s.delete_prefix(prefix), v]
186+
end
187+
end
188+
189+
exits = exits.sort_by { |name, count| -count }[0...how_many]
190+
total_exits = total_exit_count(stats)
191+
192+
top_n_total = exits.map { |name, count| count }.sum
193+
top_n_exit_pct = 100.0 * top_n_total / total_exits
194+
195+
$stderr.puts "Top-#{how_many} most frequent exit ops (#{"%.1f" % top_n_exit_pct}% of exits):"
196+
197+
longest_insn_name_len = exits.map { |name, count| name.length }.max
198+
exits.each do |name, count|
199+
padding = longest_insn_name_len + left_pad
200+
padded_name = "%#{padding}s" % name
201+
padded_count = "%10d" % count
202+
percent = 100.0 * count / total_exits
203+
formatted_percent = "%.1f" % percent
204+
$stderr.puts("#{padded_name}: #{padded_count} (#{formatted_percent})" )
205+
end
206+
end
207+
208+
def total_exit_count(stats, prefix: "exit_")
209+
total = 0
210+
stats.each do |k,v|
211+
total += v if k.start_with?(prefix)
212+
end
213+
total
154214
end
155215

156216
def print_counters(counters, prefix:, prompt:)

‎yjit_iface.c

Lines changed: 32 additions & 126 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,8 @@ static VALUE cYjitBlock;
2929
static int64_t exit_op_count[VM_INSTRUCTION_SIZE] = { 0 };
3030
struct rb_yjit_runtime_counters yjit_runtime_counters = { 0 };
3131
static VALUE cYjitCodeComment;
32+
33+
extern const int rb_vm_max_insn_name_size;
3234
#endif
3335

3436
// Machine code blocks (executable memory)
@@ -707,15 +709,26 @@ comments_for(rb_execution_context_t *ec, VALUE self, VALUE start_address, VALUE
707709
return comment_array;
708710
}
709711

710-
// Primitive called in yjit.rb. Export all runtime counters as a Ruby hash.
712+
// Primitive called in yjit.rb. Export all YJIT statistics as a Ruby hash.
711713
static VALUE
712-
get_stat_counters(rb_execution_context_t *ec, VALUE self)
714+
get_yjit_stats(rb_execution_context_t *ec, VALUE self)
713715
{
714716
#if RUBY_DEBUG
715717
if (!rb_yjit_opts.gen_stats) return Qnil;
716718

717719
VALUE hash = rb_hash_new();
718720
RB_VM_LOCK_ENTER();
721+
722+
{
723+
VALUE key = ID2SYM(rb_intern("inline_code_size"));
724+
VALUE value = LL2NUM((long long)cb->write_pos);
725+
rb_hash_aset(hash, key, value);
726+
727+
key = ID2SYM(rb_intern("outlined_code_size"));
728+
value = LL2NUM((long long)ocb->write_pos);
729+
rb_hash_aset(hash, key, value);
730+
}
731+
719732
{
720733
int64_t *counter_reader = (int64_t *)&yjit_runtime_counters;
721734
int64_t *counter_reader_end = &yjit_runtime_counters.last_member;
@@ -747,6 +760,22 @@ get_stat_counters(rb_execution_context_t *ec, VALUE self)
747760
name_reader = name_end;
748761
}
749762
}
763+
764+
{
765+
// For each entry in exit_op_count, add a stats entry with key "exit_INSTRUCTION_NAME",
766+
// where the value is the count of side exits for that instruction.
767+
768+
char key_string[rb_vm_max_insn_name_size + 6]; // Leave room for "exit_" and a final NUL
769+
for (int i = 0; i < VM_INSTRUCTION_SIZE; i++) {
770+
const char *i_name = insn_name(i); // Look up Ruby's NUL-terminated insn name string
771+
snprintf(key_string, rb_vm_max_insn_name_size + 6, "%s%s", "exit_", i_name);
772+
773+
VALUE key = ID2SYM(rb_intern(key_string));
774+
VALUE value = LL2NUM((long long)exit_op_count[i]);
775+
rb_hash_aset(hash, key, value);
776+
}
777+
}
778+
750779
RB_VM_LOCK_LEAVE();
751780
return hash;
752781
#else
@@ -768,8 +797,6 @@ reset_stats_bang(rb_execution_context_t *ec, VALUE self)
768797
#include "yjit.rbinc"
769798

770799
#if RUBY_DEBUG
771-
// implementation for --yjit-stats
772-
773800
void
774801
rb_yjit_collect_vm_usage_insn(int insn)
775802
{
@@ -795,128 +822,7 @@ rb_yjit_count_side_exit_op(const VALUE *exit_pc)
795822
exit_op_count[insn]++;
796823
return exit_pc; // This function must return exit_pc!
797824
}
798-
799-
struct insn_count {
800-
int64_t insn;
801-
int64_t count;
802-
};
803-
804-
static int
805-
insn_count_sort_comp(const void *a, const void *b)
806-
{
807-
const struct insn_count *count_a = a;
808-
const struct insn_count *count_b = b;
809-
if (count_a->count > count_b->count) {
810-
return -1;
811-
}
812-
else if (count_a->count < count_b->count) {
813-
return 1;
814-
}
815-
return 0;
816-
}
817-
818-
static struct insn_count insn_sorting_buffer[VM_INSTRUCTION_SIZE];
819-
static const struct insn_count *
820-
sort_insn_count_array(int64_t *array)
821-
{
822-
for (int i = 0; i < VM_INSTRUCTION_SIZE; i++) {
823-
insn_sorting_buffer[i] = (struct insn_count) { i, array[i] };
824-
}
825-
qsort(insn_sorting_buffer, VM_INSTRUCTION_SIZE, sizeof(insn_sorting_buffer[0]), &insn_count_sort_comp);
826-
return insn_sorting_buffer;
827-
}
828-
829-
// Compute the total interpreter exit count
830-
static int64_t
831-
calc_total_exit_count()
832-
{
833-
size_t total_exit_count = 0;
834-
for (int i = 0; i < VM_INSTRUCTION_SIZE; i++) {
835-
total_exit_count += exit_op_count[i];
836-
}
837-
838-
return total_exit_count;
839-
}
840-
841-
static void
842-
print_insn_count_buffer(int how_many, int left_pad)
843-
{
844-
size_t total_exit_count = calc_total_exit_count();
845-
846-
// Sort the exit ops by decreasing frequency
847-
const struct insn_count *sorted_exit_ops = sort_insn_count_array(exit_op_count);
848-
849-
// Compute the longest instruction name and top10_exit_count
850-
size_t longest_insn_len = 0;
851-
size_t top10_exit_count = 0;
852-
for (int i = 0; i < how_many; i++) {
853-
const char *instruction_name = insn_name(sorted_exit_ops[i].insn);
854-
size_t len = strlen(instruction_name);
855-
if (len > longest_insn_len) {
856-
longest_insn_len = len;
857-
}
858-
top10_exit_count += sorted_exit_ops[i].count;
859-
}
860-
861-
double top10_exit_percent = 100.0 * top10_exit_count / total_exit_count;
862-
863-
fprintf(stderr, "top-%d most frequent exit ops (%.1f%% of exits):\n", how_many, top10_exit_percent);
864-
865-
// Print the top-N most frequent exit counts
866-
for (int i = 0; i < how_many; i++) {
867-
const char *instruction_name = insn_name(sorted_exit_ops[i].insn);
868-
size_t padding = left_pad + longest_insn_len - strlen(instruction_name);
869-
for (size_t j = 0; j < padding; j++) {
870-
fputc(' ', stderr);
871-
}
872-
double percent = 100 * sorted_exit_ops[i].count / (double)total_exit_count;
873-
fprintf(stderr, "%s: %10" PRId64 " (%.1f%%)\n", instruction_name, sorted_exit_ops[i].count, percent);
874-
}
875-
}
876-
877-
__attribute__((destructor))
878-
static void
879-
print_yjit_stats(void)
880-
{
881-
if (!rb_yjit_opts.gen_stats) {
882-
return;
883-
}
884-
885-
// Warn if the executable code block is out of the relative
886-
// 32-bit jump range away from compiled C code
887-
ptrdiff_t start_diff = (cb->mem_block + cb->mem_size) - (uint8_t*)&print_yjit_stats;
888-
if (start_diff < INT32_MIN || start_diff > INT32_MAX) {
889-
fprintf(stderr, "WARNING: end of code block past rel32 offset range from C code\n");
890-
}
891-
892-
// Compute the total exit count
893-
int64_t total_exit_count = calc_total_exit_count();
894-
895-
// Number of instructions that finish executing in YJIT. See :count-placement:.
896-
int64_t retired_in_yjit = yjit_runtime_counters.exec_instruction - total_exit_count;
897-
898-
// Average length of instruction sequences executed by YJIT
899-
double avg_len_in_yjit = (double)retired_in_yjit / total_exit_count;
900-
901-
// Proportion of instructions that retire in YJIT
902-
int64_t total_insns_count = retired_in_yjit + yjit_runtime_counters.vm_insns_count;
903-
double ratio = retired_in_yjit / (double)total_insns_count;
904-
905-
fprintf(stderr, "compiled_iseq_count: %10" PRId64 "\n", yjit_runtime_counters.compiled_iseq_count);
906-
fprintf(stderr, "inline_code_size: %10d\n", cb->write_pos);
907-
fprintf(stderr, "outlined_code_size: %10d\n", ocb->write_pos);
908-
909-
fprintf(stderr, "total_exit_count: %10" PRId64 "\n", total_exit_count);
910-
fprintf(stderr, "total_insns_count: %10" PRId64 "\n", total_insns_count);
911-
fprintf(stderr, "vm_insns_count: %10" PRId64 "\n", yjit_runtime_counters.vm_insns_count);
912-
fprintf(stderr, "yjit_insns_count: %10" PRId64 "\n", yjit_runtime_counters.exec_instruction);
913-
fprintf(stderr, "ratio_in_yjit: %9.1f%%\n", ratio * 100);
914-
fprintf(stderr, "avg_len_in_yjit: %10.1f\n", avg_len_in_yjit);
915-
916-
// Print the top-N most frequent exit ops
917-
print_insn_count_buffer(20, 4);
918-
}
919-
#endif // if RUBY_DEBUG
825+
#endif
920826

921827
void
922828
rb_yjit_iseq_mark(const struct rb_iseq_constant_body *body)

0 commit comments

Comments
 (0)
0