8000 Add ability to trace exit locations in yjit · ruby/ruby@11283ae · GitHub
[go: up one dir, main page]
Skip to content

Commit 11283ae

Browse files
eileencodestenderlove
eileencodes
and
tenderlove
committed
Add ability to trace exit locations in yjit
When running with `--yjit-stats` turned on Ruby code can inform the user what the most common exits are. While this is useful information it doesn't tell you the source location of the code that exited or what the code that exited looks like. This change intends to fix that. To use the feature, run yjit with `--yjit-stats` and `--yjit-trace-exits`, which will record the backtrace for every exit that occurs. Users must save the output of `RubyVM::YJIT.exit_locations` to a dump file. That file can then be read by StackProf to see the code that exited and the reason. *Example usage:* Given the following script, we write to a file called `concat_array.dump` the results of `RubyVM::YJIT.exit_locations`. ```ruby def concat_array ["t", "r", *x = "u", "e"].join end 1000.times do concat_array end File.write("concat_array.dump", Marshal.dump(RubyVM::YJIT.exit_locations)) ``` When we run the file with this branch and the appropriate flags the stacktrace will be recorded. Note Stackprof needs to be installed or you need to point to the library directly. ``` ./ruby --yjit --yjit-call-threshold=1 --yjit-stats --yjit-trace-exits -I/Users/eileencodes/open_source/stackprof/lib test.rb ``` We can then read the dump file with Stackprof: ``` ./ruby -I/Users/eileencodes/open_source/stackprof/lib/ /Users/eileencodes/open_source/stackprof/bin/stackprof --text concat_array.dump ``` Results will look similar to the following: ``` ================================== Mode: () Samples: 1817 (0.00% miss rate) GC: 0 (0.00%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 1001 (55.1%) 1001 (55.1%) concatarray 335 (18.4%) 335 (18.4%) invokeblock 178 (9.8%) 178 (9.8%) send 140 (7.7%) 140 (7.7%) opt_getinlinecache ...etc... ``` Simply inspecting the `concatarray` method will give `SOURCE UNAVAILABLE` because the source is insns.def. ``` ./ruby -I/Users/eileencodes/open_source/stackprof/lib/ /Users/eileencodes/open_source/stackprof/bin/stackprof --text concat_array.dump --method concatarray ``` Result: ``` concatarray (nonexistent.def:1) samples: 1001 self (55.1%) / 1001 total (55.1%) callers: 1000 ( 99.9%) Object#concat_array 1 ( 0.1%) Gem.suffixes callees (0 total): code: SOURCE UNAVAILABLE ``` However if we go deeper to the callee we can see the exact source of the `concatarray` exit. ``` ./ruby -I/Users/eileencodes/open_source/stackprof/lib/ /Users/eileencodes/open_source/stackprof/bin/stackprof --text concat_array.dump --method Object#concat_array ``` ``` Object#concat_array (/Users/eileencodes/open_source/rust_ruby/test.rb:1) samples: 0 self (0.0%) / 1000 total (55.0%) callers: 1000 ( 100.0%) block in <main> callees (1000 total): 1000 ( 100.0%) concatarray code: | 1 | def concat_array 1000 (55.0%) | 2 | ["t", "r", *x = "u", "e"].join | 3 | end ``` The `--walk` option is recommended for this feature as it make it easier to traverse the tree of exits. *Goals of this feature:* This feature is meant to give more information when working on YJIT. The idea is that if we know what code is exiting we can decide what areas to prioritize when fixing exits. In some cases this means adding prioritizing avoiding certain exits in yjit. In more complex cases it might mean changing the Ruby code to be more performant when run with yjit. Ultimately the more information we have about what code is exiting AND why, the better we can make yjit. *Known limitations:* * Due to tracing exits, running this on large codebases like Rails can be quite slow. * On complex methods it can still be difficult to pinpoint the exact cause of an exit. * Stackprof is a requirement to to view the backtrace information from the dump file Co-authored-by: Aaron Patterson <tenderlove@ruby-lang.org>
1 parent 936e540 commit 11283ae

File tree

9 files changed

+380
-11
lines changed

9 files changed

+380
-11
lines changed

‎test/ruby/test_yjit.rb

Lines changed: 41 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -56,6 +56,11 @@ def test_yjit_stats_and_v_no_error
5656
refute_includes(stderr, "NoMethodError")
5757
end
5858

59+
def test_yjit_trace_exits_and_v_no_error
60+
_stdout, stderr, _status = EnvUtil.invoke_ruby(%w(-v --yjit-trace-exits), '', true, true)
61+
refute_includes(stderr, "NoMethodError")
62+
end
63+
5964
def test_enable_from_env_var
6065
yjit_child_env = {'RUBY_YJIT_ENABLE' => '1'}
6166
assert_in_out_err([yjit_child_env, '--version'], '') do |stdout, stderr|
@@ -68,7 +73,7 @@ def test_enable_from_env_var
6873

6974
def test_compile_setclassvariable
7075
script = 'class Foo; def self.foo; @@foo = 1; end; end; Foo.foo'
71-
assert_compiles(script, insns: %i[setclassvariable], result: 1)
76+
assert_compiles(script, insns: %i[setclassvariable], result: 1, trace_exits: true)
7277
end
7378

7479
def test_compile_getclassvariable
@@ -81,20 +86,20 @@ def test_compile_putnil
8186
end
8287

8388
def test_compile_putobject
84-
assert_compiles('true', insns: %i[putobject], result: true)
85-
assert_compiles('123', insns: %i[putobject], result: 123)
86-
assert_compiles(':foo', insns: %i[putobject], result: :foo)
89+
assert_compiles('true', insns: %i[putobject], result: true, trace_exits: true)
90+
assert_compiles('123', insns: %i[putobject], result: 123, trace_exits: true)
91+
assert_compiles(':foo', insns: %i[putobject], result: :foo, trace_exits: true)
8792
end
8893

8994
def test_compile_opt_succ
9095
assert_compiles('1.succ', insns: %i[opt_succ], result: 2)
9196
end
9297

9398
def test_compile_opt_not
94-
assert_compiles('!false', insns: %i[opt_not], result: true)
95-
assert_compiles('!nil', insns: %i[opt_not], result: true)
96-
assert_compiles('!true', insns: %i[opt_not], result: false)
97-
assert_compiles('![]', insns: %i[opt_not], result: false)
99+
assert_compiles('!false', insns: %i[opt_not], result: true, trace_exits: true)
100+
assert_compiles('!nil', insns: %i[opt_not], result: true, trace_exits: true)
101+
assert_compiles('!true', insns: %i[opt_not], result: false, trace_exits: true)
102+
assert_compiles('![]', insns: %i[opt_not], result: false, trace_exits: true)
98103
end
99104

100105
def test_compile_opt_newarray
@@ -653,14 +658,15 @@ def assert_no_exits(script)
653658
end
654659

655660
ANY = Object.new
656-
def assert_compiles(test_script, insns: [], call_threshold: 1, stdout: nil, exits: {}, result: ANY, frozen_string_literal: nil)
661+
def assert_compiles(test_script, insns: [], call_threshold: 1, stdout: nil, exits: {}, trace_exits: false, result: ANY, frozen_string_literal: nil)
657662
reset_stats = <<~RUBY
658663
RubyVM::YJIT.runtime_stats
659664
RubyVM::YJIT.reset_stats!
660665
RUBY
661666

662667
write_results = <<~RUBY
663668
stats = RubyVM::YJIT.runtime_stats
669+
exit_locations = #{trace_exits} ? RubyVM::YJIT.exit_locations : nil
664670
665671
def collect_insns(iseq)
666672
insns = RubyVM::YJIT.insns_compiled(iseq)
@@ -673,7 +679,8 @@ def collect_insns(iseq)
673679
result: #{result == ANY ? "nil" : "result"},
674680
stats: stats,
675681
insns: collect_insns(iseq),
676-
disasm: iseq.disasm
682+
disasm: iseq.disasm,
683+
exit_locations: exit_locations
677684
})
678685
RUBY
679686

@@ -700,6 +707,7 @@ def collect_insns(iseq)
700707
runtime_stats = stats[:stats]
701708
insns_compiled = stats[:insns]
702709
disasm = stats[:disasm]
710+
exit_locations = stats[:exit_locations]
703711

704712
# Check that exit counts are as expected
705713
# Full stats are only available when --enable-yjit=dev
@@ -729,6 +737,27 @@ def collect_insns(iseq)
729737
flunk "Expected to compile instructions #{missed_insns.join(", ")} but didn't.\niseq:\n#{disasm}"
730738
end
731739
end
740+
741+
if exit_locations
742+
assert exit_locations.key?(:raw)
743+
assert exit_locations.key?(:frames)
744+
assert exit_locations.key?(:lines)
745+
assert exit_locations.key?(:samples)
746+
assert exit_locations.key?(:missed_samples)
747+
assert exit_locations.key?(:gc_samples)
748+
749+
assert_equal 0, exit_locations[:missed_samples]
750+
assert_equal 0, exit_locations[:gc_samples]
751+
752+
assert_not_empty exit_locations[:raw]
753+
assert_not_empty exit_locations[:frames]
754+
assert_not_empty exit_locations[:lines]
755+
756+
exit_locations[:frames].each do |frame_id, frame|
757+
assert frame.key?(:samples)
758+
assert frame.key?(:edges)
759+
end
760+
end
732761
end
733762

734763
def script_shell_encode(s)
@@ -740,7 +769,8 @@ def eval_with_jit(script, call_threshold: 1, timeout: 1000)
740769
args = [
741770
"--disable-gems",
742771
"--yjit-call-threshold=#{call_threshold}",
743-
"--yjit-stats"
772+
"--yjit-stats",
773+
"--yjit-trace-exits"
744774
]
745775
args << "-e" << script_shell_encode(script)
746776
stats_r, stats_w = IO.pipe

‎yjit.c

Lines changed: 85 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@
2525
#include "probes.h"
2626
#include "probes_helper.h"
2727
#include "iseq.h"
28+
#include "ruby/debug.h"
2829

2930
// For mmapp(), sysconf()
3031
#ifndef _WIN32
@@ -83,6 +84,88 @@ rb_yjit_mark_executable(void *mem_block, uint32_t mem_size)
8384
}
8485
}
8586

87+
# define PTR2NUM(x) (rb_int2inum((intptr_t)(void *)(x)))
88+
89+
// For a given raw sample index, add frames to the
90+
// frames hash.
91+
static void
92+
rb_yjit_add_frame(VALUE hash, VALUE frame)
93+
{
94+
VALUE frame_id = PTR2NUM(frame);
95+
96+
if (RTEST(rb_hash_aref(hash, frame_id))) {
97+
return;
98+
} else {
99+
VALUE frame_info = rb_hash_new();
100+
VALUE name = rb_profile_frame_full_label(frame);
101+
VALUE file = rb_profile_frame_absolute_path(frame);
102+
VALUE line = rb_profile_frame_first_lineno(frame);
103+
104+
if (NIL_P(file)) {
105+
file = rb_profile_frame_path(frame);
106+
}
107+
108+
rb_hash_aset(frame_info, ID2SYM(rb_intern("name")), name);
109+
rb_hash_aset(frame_info, ID2SYM(rb_intern("file")), file);
110+
111+
if (line != INT2FIX(0)) {
112+
rb_hash_aset(frame_info, ID2SYM(rb_intern("line")), line);
113+
}
114+
115+
rb_hash_aset(hash, frame_id, frame_info);
116+
}
117+
}
118+
119+
// Parses the yjit_raw_samples and yjit_line_samples data into three
120+
// hashes (raw, lines, and frames) to be used by RubyVM::YJIT.exit_locations.
121+
VALUE
122+
rb_yjit_exit_locations_dict(VALUE *yjit_raw_samples, int *yjit_line_samples, int samples_len)
123+
{
124+
VALUE result = rb_hash_new();
125+
VALUE raw_samples = rb_ary_new_capa(samples_len);
126+
VALUE line_samples = rb_ary_new_capa(samples_len);
127+
VALUE frames = rb_hash_new();
128+
int idx = 0;
129+
130+
// While the index is less than the length of raw_samples,
131+
// parse the yjit_raw_samples and yjit_line samples, then
132+
// add to raw_samples and line_samples array.
133+
while (idx < samples_len) {
134+
int num = (int)yjit_raw_samples[idx];
135+
int line_num = (int)yjit_line_samples[idx];
136+
idx++;
137+
138+
rb_ary_push(raw_samples, SIZET2NUM(num));
139+
rb_ary_push(line_samples, INT2NUM(line_num));
140+
141+
// Loop through the length of yjit_line_samples and for each
142+
// add to the frames hash. Also push the index onto the raw_samples
143+
// and line_samples arrary respectively.
144+
for (int o = 0; o < num; o++) {
145+
rb_yjit_add_frame(frames, yjit_raw_samples[idx]);
146+
rb_ary_push(raw_samples, SIZET2NUM(yjit_raw_samples[idx]));
147+
rb_ary_push(line_samples, INT2NUM(yjit_line_samples[idx]));
148+
idx++;
149+
}
150+
151+
rb_ary_push(raw_samples, SIZET2NUM(yjit_raw_samples[idx]));
152+
rb_ary_push(line_samples, INT2NUM(yjit_line_samples[idx]));
153+
idx++;
154+
155+
rb_ary_push(raw_samples, SIZET2NUM(yjit_raw_samples[idx]));
156+
rb_ary_push(line_samples, INT2NUM(yjit_line_samples[idx]));
157+
idx++;
158+
}
159+
160+
// Set add the raw_samples, line_samples, and frames to the results
161+
// hash.
162+
rb_hash_aset(result, ID2SYM(rb_intern("raw")), raw_samples);
163+
rb_hash_aset(result, ID2SYM(rb_intern("lines")), line_samples);
164+
rb_hash_aset(result, ID2SYM(rb_intern("frames")), frames);
165+
166+
return result;
167+
}
168+
86169
uint32_t
87170
rb_yjit_get_page_size(void)
88171
{
@@ -860,12 +943,14 @@ rb_yjit_invalidate_all_method_lookup_assumptions(void)
860943

861944
// Primitives used by yjit.rb
862945
VALUE rb_yjit_stats_enabled_p(rb_execution_context_t *ec, VALUE self);
946+
VALUE rb_yjit_trace_exit_locations_enabled_p(rb_execution_context_t *ec, VALUE self);
863947
VALUE rb_yjit_get_stats(rb_execution_context_t *ec, VALUE self);
864948
VALUE rb_yjit_reset_stats_bang(rb_execution_context_t *ec, VALUE self);
865949
VALUE rb_yjit_disasm_iseq(rb_execution_context_t *ec, VALUE self, VALUE iseq);
866950
VALUE rb_yjit_insns_compiled(rb_execution_context_t *ec, VALUE self, VALUE iseq);
867951
VALUE rb_yjit_simulate_oom_bang(rb_execution_context_t *ec, VALUE self);
868952
VALUE rb_yjit_get_stats(rb_execution_context_t *ec, VALUE self);
953+
VALUE rb_yjit_get_exit_locations(rb_execution_context_t *ec, VALUE self);
869954

870955
// Preprocessed yjit.rb generated during build
871956
#include "yjit.rbinc"

‎yjit.rb

Lines changed: 91 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,11 +18,102 @@ def self.stats_enabled?
1818
Primitive.rb_yjit_stats_enabled_p
1919
end
2020

21+
# Check if rb_yjit_trace_exit_locations_enabled_p is enabled.
22+
def self.trace_exit_locations_enabled?
23+
Primitive.rb_yjit_trace_exit_locations_enabled_p
24+
end
25+
2126
# Discard statistics collected for --yjit-stats.
2227
def self.reset_stats!
2328
Primitive.rb_yjit_reset_stats_bang
2429
end
2530

31+
# If --yjit-trace-exits is enabled parse the hashes from
32+
# Primitive.rb_yjit_get_exit_locations into a format readable
33+
# by StackProf. This will allow us to find the exact location of a
34+
# side exit in YJIT based on the instruction that is exiting.
35+
#
36+
# Usage:
37+
#
38+
# In a script call:
39+
#
40+
# File.write("my_file.dump", Marshal.dump(RubyVM::YJIT.exit_locations))
41+
#
42+
# Then run the file with the following options:
43+
#
44+
# ruby --yjit --yjit-stats --yjit-trace-exits test.rb
45+
#
46+
# Once the code is done running, use StackProf to read the dump file.
47+
# See StackProf documentation for options.
48+
def self.exit_locations
49+
return unless trace_exit_locations_enabled?
50+
51+
results = Primitive.rb_yjit_get_exit_locations
52+
raw_samples = results[:raw].dup
53+
line_samples = results[:lines].dup
54+
frames = results[:frames].dup
55+
samples_count = 0
56+
57+
frames.each do |frame_id, frame|
58+
frame[:samples] = 0
59+
frame[:edges] = {}
60+
end
61+
62+
# Loop through the instructions and set the frame hash with the data.
63+
# We use nonexistent.def for the file name, otherwise insns.def will be displayed
64+
# and that information isn't useful in this context.
65+
RubyVM::INSTRUCTION_NAMES.each_with_index do |name, frame_id|
66+
frame_hash = { samples: 0, total_samples: 0, edges: {}, name: name, file: "nonexistent.def", line: nil }
67+
results[:frames][frame_id] = frame_hash
68+
frames[frame_id] = frame_hash
69+
end
70+
71+
# Loop through the raw_samples and build the hashes for StackProf.
72+
# The loop is based off an example in the StackProf documentation and therefore
73+
# this functionality can only work with that library.
74+
while raw_samples.length > 0
75+
stack_trace = raw_samples.shift(raw_samples.shift + 1)
76+
lines = line_samples.shift(line_samples.shift + 1)
77+
prev_frame_id = nil
78+
79+
stack_trace.each_with_index do |frame_id, idx|
80+
if prev_frame_id
81+
prev_frame = frames[prev_frame_id]
82+
prev_frame[:edges][frame_id] ||= 0
83+
prev_frame[:edges][frame_id] += 1
84+
end
85+
86+
frame_info = frames[frame_id]
87+
frame_info[:total_samples] ||= 0
88+
frame_info[:total_samples] += 1
89+
90+
frame_info[:lines] ||= {}
91+
frame_info[:lines][lines[idx]] ||= [0, 0]
92+
frame_info[:lines][lines[idx]][0] += 1
93+
94+
prev_frame_id = frame_id
95+
end
96+
97+
top_frame_id = stack_trace.last
98+
top_frame_line = 1
99+
100+
frames[top_frame_id][:samples] += 1
101+
frames[top_frame_id][:lines] ||= {}
102+
frames[top_frame_id][:lines][top_frame_line] ||= [0, 0]
103+
frames[top_frame_id][:lines][top_frame_line][1] += 1
104+
105+
samples_count += raw_samples.shift
106+
line_samples.shift
107+
end
108+
109+
results[:samples] = samples_count
110+
# Set missed_samples and gc_samples to 0 as their values
111+
# don't matter to us in this context.
112+
results[:missed_samples] = 0
113+
results[:gc_samples] = 0
114+
results
115+
end
116+
26117
# Return a hash for statistics generated for the --yjit-stats command line option.
27118
# Return nil when option is not passed or unavailable.
28119
def self.runtime_stats

‎yjit/bindgen/src/main.rs

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -239,6 +239,7 @@ fn main() {
239239
.allowlist_function("rb_yjit_obj_written")
240240
.allowlist_function("rb_yjit_str_simple_append")
241241
.allowlist_function("rb_ENCODING_GET")
242+
.allowlist_function("rb_yjit_exit_locations_dict")
242243

243244
// from vm_sync.h
244245
.allowlist_function("rb_vm_barrier")
@@ -273,6 +274,9 @@ fn main() {
273274
.allowlist_function("rb_class_allocate_instance")
274275
.allowlist_function("rb_obj_info")
275276

277+
// From include/ruby/debug.h
278+
.allowlist_function("rb_profile_frames")
279+
276280
// We define VALUE manually, don't import it
277281
.blocklist_type("VALUE")
278282

0 commit comments

Comments
 (0)
0