Skip to content

Commit

Permalink
Rework tracing for blocks running as methods
Browse files Browse the repository at this point in the history 
The main impetus for this change is to fix [Bug #13392]. Previously, we
fired the "return" TracePoint event after popping the stack frame for
the block running as method (BMETHOD). This gave undesirable source
location outputs as the return event normally fires right before the
frame going away.

The iseq for each block can run both as a block and as a method. To
accommodate that, this commit makes vm_trace() fire call/return events for
instructions that have b_call/b_return events attached when the iseq is
running as a BMETHOD. The logic for rewriting to "trace_*" instruction
is tweaked so that when the user listens to call/return events,
instructions with b_call/b_return become trace variants.

To continue to provide the return value for non-local returns done using
the "return" or "break" keyword inside BMETHODs, the stack unwinding
code is tweaked. b_return events now provide the same return value as
return events for these non-local cases. A pre-existing test deemed not
providing a return value for these b_return events as a limitation.

This commit removes the checks for call/return TracePoint events that
happen when calling into BMETHODs when no TracePoints are active.
Technically, migrating just the return event is enough to fix the bug,
but migrating both call and return removes our reliance on
`VM_FRAME_FLAG_FINISH` and re-entering the interpreter when the caller
is already in the interpreter.
  • Loading branch information
@XrXr
XrXr committed Dec 1, 2021
1 parent 3b2b28d commit 9121e57
Show file tree
Hide file tree
Showing 6 changed files with 210 additions and 60 deletions.
25 changes: 23 additions & 2 deletions iseq.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3310,6 +3310,23 @@ rb_iseq_trace_flag_cleared(const rb_iseq_t *iseq, size_t pos)
encoded_iseq_trace_instrument(&iseq_encoded[pos], 0, false);
}

// We need to fire call events on instructions with b_call events if the block
// is running as a method. So, if we are listening for call events, then
// instructions that have b_call events need to become trace variants.
// Use this function when making decisions about recompiling to trace variants.
static inline rb_event_flag_t
add_bmethod_events(rb_event_flag_t events)
{
if (events & RUBY_EVENT_CALL) {
events |= RUBY_EVENT_B_CALL;
}
if (events & RUBY_EVENT_RETURN) {
events |= RUBY_EVENT_B_RETURN;
}
return events;
}

// Note, to support call/return events for bmethods, turnon_event can have more events than tpval.
static int
iseq_add_local_tracepoint(const rb_iseq_t *iseq, rb_event_flag_t turnon_events, VALUE tpval, unsigned int target_line)
{
Expand Down Expand Up @@ -3365,9 +3382,12 @@ iseq_add_local_tracepoint_i(const rb_iseq_t *iseq, void *p)
}

int
rb_iseq_add_local_tracepoint_recursively(const rb_iseq_t *iseq, rb_event_flag_t turnon_events, VALUE tpval, unsigned int target_line)
rb_iseq_add_local_tracepoint_recursively(const rb_iseq_t *iseq, rb_event_flag_t turnon_events, VALUE tpval, unsigned int target_line, bool target_bmethod)
{
struct trace_set_local_events_struct data;
if (target_bmethod) {
turnon_events = add_bmethod_events(turnon_events);
}
data.turnon_events = turnon_events;
data.tpval = tpval;
data.target_line = target_line;
Expand Down Expand Up @@ -3399,6 +3419,7 @@ iseq_remove_local_tracepoint(const rb_iseq_t *iseq, VALUE tpval)
((rb_iseq_t *)iseq)->aux.exec.local_hooks = NULL;
}

local_events = add_bmethod_events(local_events);
for (pc = 0; pc<body->iseq_size;) {
rb_event_flag_t pc_events = rb_iseq_event_flags(iseq, pc);
pc += encoded_iseq_trace_instrument(&iseq_encoded[pc], pc_events & (local_events | iseq->aux.exec.global_trace_events), false);
Expand Down Expand Up @@ -3449,7 +3470,7 @@ rb_iseq_trace_set(const rb_iseq_t *iseq, rb_event_flag_t turnon_events)
rb_event_flag_t enabled_events;
rb_event_flag_t local_events = iseq->aux.exec.local_hooks ? iseq->aux.exec.local_hooks->events : 0;
((rb_iseq_t *)iseq)->aux.exec.global_trace_events = turnon_events;
enabled_events = turnon_events | local_events;
enabled_events = add_bmethod_events(turnon_events | local_events);

for (pc=0; pc<body->iseq_size;) {
rb_event_flag_t pc_events = rb_iseq_event_flags(iseq, pc);
Expand Down
2 changes: 1 addition & 1 deletion iseq.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -160,7 +160,7 @@ const rb_iseq_t *rb_iseq_ibf_load(VALUE str);
const rb_iseq_t *rb_iseq_ibf_load_bytes(const char *cstr, size_t);
VALUE rb_iseq_ibf_load_extra_data(VALUE str);
void rb_iseq_init_trace(rb_iseq_t *iseq);
int rb_iseq_add_local_tracepoint_recursively(const rb_iseq_t *iseq, rb_event_flag_t turnon_events, VALUE tpval, unsigned int target_line);
int rb_iseq_add_local_tracepoint_recursively(const rb_iseq_t *iseq, rb_event_flag_t turnon_events, VALUE tpval, unsigned int target_line, bool target_bmethod);
int rb_iseq_remove_local_tracepoint_recursively(const rb_iseq_t *iseq, VALUE tpval);
const rb_iseq_t *rb_iseq_load_iseq(VALUE fname);

Expand Down
122 changes: 116 additions & 6 deletions test/ruby/test_settracefunc.rb
View file
Original file line number Diff line number Diff line change
Expand Up @@ -393,7 +393,7 @@ def test_trace_defined_method
[["c-return", 3, :set_trace_func, Kernel],
["line", 6, __method__, self.class],
["call", 1, :foobar, FooBar],
["return", 6, :foobar, FooBar],
["return", 1, :foobar, FooBar],
["line", 7, __method__, self.class],
["c-call", 7, :set_trace_func, Kernel]].each{|e|
assert_equal(e, events.shift)
Expand Down Expand Up @@ -1951,7 +1951,7 @@ def test_return_value_with_rescue
end

define_method(:f_break_defined) do
return :f_break_defined
break :f_break_defined
end

define_method(:f_raise_defined) do
Expand All @@ -1972,27 +1972,44 @@ def test_return_value_with_rescue_and_defined_methods
tp_return_value(:f_last_defined),
'[Bug #13369]'

assert_equal [[:b_return, :f_return_defined, nil], # current limitation
assert_equal [[:b_return, :f_return_defined, :f_return_defined],
[:return, :f_return_defined, :f_return_defined]],
tp_return_value(:f_return_defined),
'[Bug #13369]'

assert_equal [[:b_return, :f_break_defined, nil],
assert_equal [[:b_return, :f_break_defined, :f_break_defined],
[:return, :f_break_defined, :f_break_defined]],
tp_return_value(:f_break_defined),
'[Bug #13369]'

assert_equal [[:b_return, :f_raise_defined, nil],
assert_equal [[:b_return, :f_raise_defined, f_raise_defined],
[:return, :f_raise_defined, f_raise_defined]],
tp_return_value(:f_raise_defined),
'[Bug #13369]'

assert_equal [[:b_return, :f_break_in_rescue_defined, nil],
assert_equal [[:b_return, :f_break_in_rescue_defined, f_break_in_rescue_defined],
[:return, :f_break_in_rescue_defined, f_break_in_rescue_defined]],
tp_return_value(:f_break_in_rescue_defined),
'[Bug #13369]'
end

define_method(:just_yield) do |&block|
block.call
end

define_method(:unwind_multiple_bmethods) do
just_yield { return :unwind_multiple_bmethods }
end

def test_non_local_return_across_multiple_define_methods
assert_equal [[:b_return, :unwind_multiple_bmethods, nil],
[:b_return, :just_yield, nil],
[:return, :just_yield, nil],
[:b_return, :unwind_multiple_bmethods, :unwind_multiple_bmethods],
[:return, :unwind_multiple_bmethods, :unwind_multiple_bmethods]],
tp_return_value(:unwind_multiple_bmethods)
end

def f_iter
yield
end
Expand Down Expand Up @@ -2403,6 +2420,99 @@ def test_enable_target_thread
assert_equal Array.new(2){th}, events
end

def test_return_bmethod_location
bug13392 = "[ruby-core:80515] incorrect bmethod return location"
actual = nil
obj = Object.new
expected = __LINE__ + 1
obj.define_singleton_method(:t){}
tp = TracePoint.new(:return) do
next unless target_thread?
actual = tp.lineno
end
tp.enable {obj.t}
assert_equal(expected, actual, bug13392)
end

def test_b_tracepoints_going_away
# test that call and return TracePoints continue to work
# when b_call and b_return TracePoints stop
events = []
record_events = ->(tp) do
next unless target_thread?
events << [tp.event, tp.method_id]
end

call_ret_tp = TracePoint.new(:call, :return, &record_events)
block_call_ret_tp = TracePoint.new(:b_call, :b_return, &record_events)

obj = Object.new
obj.define_singleton_method(:foo) {} # a bmethod

foo = obj.method(:foo)
call_ret_tp.enable(target: foo) do
block_call_ret_tp.enable(target: foo) do
obj.foo
end
obj.foo
end

assert_equal(
[
[:call, :foo],
[:b_call, :foo],
[:b_return, :foo],
[:return, :foo],
[:call, :foo],
[:return, :foo],
],
events,
)
end

def test_target_different_bmethod_same_iseq
# make two bmethods that share the same block iseq
block = Proc.new {}
obj = Object.new
obj.define_singleton_method(:one, &block)
obj.define_singleton_method(:two, &block)

events = []
record_events = ->(tp) do
next unless target_thread?
events << [tp.event, tp.method_id]
end
tp_one = TracePoint.new(:call, :return, &record_events)
tp_two = TracePoint.new(:call, :return, &record_events)

tp_one.enable(target: obj.method(:one)) do
obj.one
obj.two # not targeted
end
assert_equal([[:call, :one], [:return, :one]], events)
events.clear

tp_one.enable(target: obj.method(:one)) do
obj.one
tp_two.enable(target: obj.method(:two)) do
obj.two
end
obj.two
obj.one
end
assert_equal(
[
[:call, :one],
[:return, :one],
[:call, :two],
[:return, :two],
[:call, :one],
[:return, :one],
],
events
)
end

def test_return_event_with_rescue
obj = Object.new
def obj.example
Expand Down
73 changes: 32 additions & 41 deletions vm.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1313,7 +1313,6 @@ invoke_bmethod(rb_execution_context_t *ec, const rb_iseq_t *iseq, VALUE self, co
/* bmethod */
int arg_size = iseq->body->param.size;
VALUE ret;
rb_hook_list_t *hooks;

VM_ASSERT(me->def->type == VM_METHOD_TYPE_BMETHOD);

Expand All @@ -1325,24 +1324,9 @@ invoke_bmethod(rb_execution_context_t *ec, const rb_iseq_t *iseq, VALUE self, co
iseq->body->local_table_size - arg_size,
iseq->body->stack_max);

RUBY_DTRACE_METHOD_ENTRY_HOOK(ec, me->owner, me->def->original_id);
EXEC_EVENT_HOOK(ec, RUBY_EVENT_CALL, self, me->def->original_id, me->called_id, me->owner, Qnil);

if (UNLIKELY((hooks = me->def->body.bmethod.hooks) != NULL) &&
hooks->events & RUBY_EVENT_CALL) {
rb_exec_event_hook_orig(ec, hooks, RUBY_EVENT_CALL, self,
me->def->original_id, me->called_id, me->owner, Qnil, FALSE);
}
VM_ENV_FLAGS_SET(ec->cfp->ep, VM_FRAME_FLAG_FINISH);
ret = vm_exec(ec, true);

EXEC_EVENT_HOOK(ec, RUBY_EVENT_RETURN, self, me->def->original_id, me->called_id, me->owner, ret);
if ((hooks = me->def->body.bmethod.hooks) != NULL &&
hooks->events & RUBY_EVENT_RETURN) {
rb_exec_event_hook_orig(ec, hooks, RUBY_EVENT_RETURN, self,
me->def->original_id, me->called_id, me->owner, ret, FALSE);
}
RUBY_DTRACE_METHOD_RETURN_HOOK(ec, me->owner, me->def->original_id);
return ret;
}

Expand Down Expand Up @@ -2033,9 +2017,11 @@ frame_name(const rb_control_frame_t *cfp)
}
#endif

// cfp_returning_with_value:
// Whether cfp is the last frame in the unwinding process for a non-local return.
static void
hook_before_rewind(rb_execution_context_t *ec, const rb_control_frame_t *cfp,
int will_finish_vm_exec, int state, struct vm_throw_data *err)
bool cfp_returning_with_value, int state, struct vm_throw_data *err)
{
if (state == TAG_RAISE && RBASIC(err)->klass == rb_eSysStackError) {
return;
Expand All @@ -2058,32 +2044,36 @@ hook_before_rewind(rb_execution_context_t *ec, const rb_control_frame_t *cfp,
break;
case VM_FRAME_MAGIC_BLOCK:
if (VM_FRAME_BMETHOD_P(ec->cfp)) {
EXEC_EVENT_HOOK(ec, RUBY_EVENT_B_RETURN, ec->cfp->self, 0, 0, 0, frame_return_value(err));
VALUE bmethod_return_value = frame_return_value(err);
if (cfp_returning_with_value) {
// Non-local return terminating at a BMETHOD control frame.
bmethod_return_value = THROW_DATA_VAL(err);
}


EXEC_EVENT_HOOK(ec, RUBY_EVENT_B_RETURN, ec->cfp->self, 0, 0, 0, bmethod_return_value);
if (UNLIKELY(local_hooks && local_hooks->events & RUBY_EVENT_B_RETURN)) {
rb_exec_event_hook_orig(ec, local_hooks, RUBY_EVENT_B_RETURN,
ec->cfp->self, 0, 0, 0, frame_return_value(err), FALSE);
ec->cfp->self, 0, 0, 0, bmethod_return_value, FALSE);
}

if (!will_finish_vm_exec) {
const rb_callable_method_entry_t *me = rb_vm_frame_method_entry(ec->cfp);

/* kick RUBY_EVENT_RETURN at invoke_block_from_c() for bmethod */
EXEC_EVENT_HOOK_AND_POP_FRAME(ec, RUBY_EVENT_RETURN, ec->cfp->self,
rb_vm_frame_method_entry(ec->cfp)->def->original_id,
rb_vm_frame_method_entry(ec->cfp)->called_id,
rb_vm_frame_method_entry(ec->cfp)->owner,
frame_return_value(err));

VM_ASSERT(me->def->type == VM_METHOD_TYPE_BMETHOD);
local_hooks = me->def->body.bmethod.hooks;

if (UNLIKELY(local_hooks && local_hooks->events & RUBY_EVENT_RETURN)) {
rb_exec_event_hook_orig(ec, local_hooks, RUBY_EVENT_RETURN, ec->cfp->self,
rb_vm_frame_method_entry(ec->cfp)->def->original_id,
rb_vm_frame_method_entry(ec->cfp)->called_id,
rb_vm_frame_method_entry(ec->cfp)->owner,
frame_return_value(err), TRUE);
}
const rb_callable_method_entry_t *me = rb_vm_frame_method_entry(ec->cfp);

EXEC_EVENT_HOOK_AND_POP_FRAME(ec, RUBY_EVENT_RETURN, ec->cfp->self,
rb_vm_frame_method_entry(ec->cfp)->def->original_id,
rb_vm_frame_method_entry(ec->cfp)->called_id,
rb_vm_frame_method_entry(ec->cfp)->owner,
bmethod_return_value);

VM_ASSERT(me->def->type == VM_METHOD_TYPE_BMETHOD);
local_hooks = me->def->body.bmethod.hooks;

if (UNLIKELY(local_hooks && local_hooks->events & RUBY_EVENT_RETURN)) {
rb_exec_event_hook_orig(ec, local_hooks, RUBY_EVENT_RETURN, ec->cfp->self,
rb_vm_frame_method_entry(ec->cfp)->def->original_id,
rb_vm_frame_method_entry(ec->cfp)->called_id,
rb_vm_frame_method_entry(ec->cfp)->owner,
bmethod_return_value, TRUE);
}
THROW_DATA_CONSUMED_SET(err);
}
Expand Down Expand Up @@ -2284,7 +2274,8 @@ vm_exec_handle_exception(rb_execution_context_t *ec, enum ruby_tag_type state,
if (catch_iseq == NULL) {
ec->errinfo = Qnil;
THROW_DATA_CATCH_FRAME_SET(err, cfp + 1);
hook_before_rewind(ec, ec->cfp, TRUE, state, err);
// cfp == escape_cfp here so calling with cfp_returning_with_value = true
hook_before_rewind(ec, ec->cfp, true, state, err);
rb_vm_pop_frame(ec);
return THROW_DATA_VAL(err);
}
Expand Down Expand Up @@ -2425,7 +2416,7 @@ vm_exec_handle_exception(rb_execution_context_t *ec, enum ruby_tag_type state,
return Qundef;
}
else {
hook_before_rewind(ec, ec->cfp, FALSE, state, err);
hook_before_rewind(ec, ec->cfp, (cfp == escape_cfp), state, err);

if (VM_FRAME_FINISHED_P(ec->cfp)) {
rb_vm_pop_frame(ec);
Expand Down

0 comments on commit 9121e57

Please sign in to comment.