Trace event for block/scope end?

[James M. Lawrence]

(Since I'm sure Rocky will know about this, I was reluctant to stir
traffic on ruby-core.)

Is there a reason that there is no trace event for a block ending? It
would seem useful to know when a scope has vanished.

tracer = lambda do |event, file, line, method, binding, klass|
printf("%-10s %-04s %-06s\n", event, line, method.inspect)
end

set_trace_func(tracer)
# -line-
class A # 7
nil # 8
end # 9 <--- class end event
# 10
1.times do # 11
nil # 12
end # 13 <--- no block/scope end event
# 14
nil # 15

### output:

c-return 5 :set_trace_func
line 7 nil
c-call 7 :inherited
c-return 7 :inherited
class 7 nil
line 8 nil
end 9 nil <--- class end event
line 11 nil
c-call 11 :times
line 12 nil
c-return 11 :times
line 15 nil (nothing for block/scope end)

This is a complication for Binding.of_caller
(http://github.com/quix/binding_of_caller/blob/master/binding_of_caller.rb).

I have one legitimate use for Binding.of_caller (and a thousand
illegitimate ones :)

[James M. Lawrence]

Forgot to mention--the sample code and Binding.of_caller are for MRI
1.9.2.

[Rocky Bernstein]

Let's review how the contended part of the trace is call working. 

The program calls C function "times" with a block. That C function yields back to the block possibly several times. It is true that the yielding back and forth doesn't trigger a "yield" or scope switch event. 

When "times" finally returns, there's a c-return event and that shows up.  So what I think you are noticing and asking about is not that you aren't getting the (final) return out of the block, but that the switching of scope between times and the block is not shown. 

But also note that you can't really get much scope information from inside a C function anyway. And probably because of that, most people only think there is one scope anyway. Therefore people don't find the trace (or debugging a trace) too surprising if the yield to and from C is missing.

If you rewrite the code in Ruby ,courtesy of a stripped down version from rubinius  (noting differences because I can't really create a singleton method for 1.times), one gets:  

tracer = lambda do |event, file, line, method, binding, klass|

  printf("%-10s %-04s %-06s\n", event, line, method.inspect)

end

class One

  def initialize

    @x = 1

  end

  def times

    i = 0

    while i < @x

      yield i # 11

      i += 1  # 12 

    end

    self

  end

end

x = One.new

set_trace_func(tracer)

x.times do   # 19

  nil        # 20

end          # 21

If one runs this, one sees: 

...

line       11   :times

line       20   nil   

line       12   :times

...

That said, what to do? Let's compare with what happens in other Rubies.

In 1.8 there are some slight differences elsewhere but other than these, 1.8.7 gives the same trace: no special yield event. And in fact in neither is there such an event type.

Rubinius is kind of interesting in that there's very little support in the kernel for stepping. There are no "events' as there are in MRI or YARV.

Instead, there is breakpoint support and the logic for where to stop next is largely determined from outside the kernel.  As a result, "finish" or "step out" in the trepanning debugger does the right thing (except when there are bugs.) 

So with a little pain, inside the trace handler in YARV 1.9.2 one could scan to see if straight-line code contains a "leave" instruction and set a breakpoint there. But I think I'd agree that a better solution would be to add some sort of "yield" event as a hook callback, even if it slows things down a negligible amount. 

One could also try persuade ruby-core developers to consider "yield" as some sort of "return". But as with the eval location reporting, I think that's conceptually wrong and one will just get into tedious discussions about in what contexts is it *really* a "return".  

Given that there's never been any support for this there, and adding it properly means adding a new event type, I think getting this changed in YARV might offer resistance and a bit of time to implement (like 1-2 years). I can consider a change to the patched YARV, and it will especially go in faster if you want to code it up. Basically one would look at how VM instruction stepping was patched; that will show you the specific files and places to change. E.g. where the new event define goes, and suggests how to patch  a VM instruction (in this case it would be "leave"). 

And finally and most importantly, I'm not a Ruby core committer. I don't know that suggestions I've made carried any weight. By all means ask on ruby-core and/or submit a patch and don't get discouraged if you don't hear back. 

I looked at the code. I appreciate the hoops one has to go through to make this work in an unpatched Ruby via set_trace_func. And to handle "yield" you'll  need even more arcane stuff like adding breakpoints and scanning instructions for "leave" or a patch to Ruby.

But I've already patched YARV 1.9.2 so that this is built in. In rb-threadframe it's called RubyVM::ThreadFrame.current.prev and takes an optional number of how many frames previous you want to go back. (I really should drop the "current" part. RubyVM::ThreadFrame which everyone finds awkward was my not my original suggested name.)  Or if you want another approach in an unpatched 1.9.2, I believe ruby-debug19 has Kernel.binding_n which I believe does this.

Furthermore, when I look at the patch in Redmine where you change the setting of that C local variable "tracing" I instinctively get nervous.  Your patch may be perfect, but I've had a lot of problems with changing that and it's cause obscure SEGV's in hard to reproduce situations in the debugger. To do a full job, one probably needs a lot more test cases than the one you have in the patch.

The reason for that variable is to make sure you aren't tracing inside the trace hook. The end of August at Ruby Kaigi 2010, I asked about having that variable be reset under user control. That is if you want to reset it, you issue a call to do so. That way in this very specific situation you can reset it, but not have to worry about the damage it may cause to other trace hooks.  

My use of resetting is that inside a debugger, I want to make a nested call to the debugger to trace some code I enter in the debugger. 

[James M. Lawrence]

Thank you for the informative reply. It's good to know how deep the
issue goes. It is understandable that nobody cared enough about a
vanishing block scope in order to make it an event, whereas changing
class/method scopes is important. It's the difference between taking
off a hat and changing whole outfits.

> Furthermore, when I look at the patch in Redmine where you change the
> setting of that C local variable "tracing" I instinctively get nervous.
> Your patch may be perfect, but I've had a lot of problems with changing
> that and it's cause obscure SEGV's in hard to reproduce situations in the
> debugger. To do a full job, one probably needs a lot more test cases than
> the one you have in the patch.

In this case I think the patch is just a band-aid for the underlying
brokenness of continuations. Even the most intensive multi-threaded
code has balanced PUSH_TAGs and POP_TAGs. But a simple continuation
example from the documentation produces more PUSH_TAGs than POP_TAGs.
Though I've not investigated in detail, it seems evident that this is
a bad thing. My patch just clears the flag which would have been
cleared had PUSH_TAG and POP_TAG been balanced (the code preceding a
POP_TAG is supposed to clear it, but that code is never executed).

[Rocky Bernstein]

On Sun, Feb 13, 2011 at 5:39 PM, James M. Lawrence <quixotic...@gmail.com> wrote:

Thank you for the informative reply. It's good to know how deep the
issue goes. It is understandable that nobody cared enough about a
vanishing block scope in order to make it an event, whereas changing
class/method scopes is important.

I am not sure I understand why it is understandable that switching scope any less important than some of the other events that are there. I've used the relatively obscure class-creation event. See https://gist.github.com/825393 for example. But I'm not sure I would go so far as to say that's more important than yielding inside a block or leaving a block which was yielded to. In fact, you had I think a valid use of it even if there may be other ways to implement this.  

I mentioned two ways one might implement capturing such an event. In fact there's a third way which is done in debuggers. You could capture all line events and query the stack to see if things have changed.  This of course is slow. It also makes for more complex code. 

Since I want the debugger "finish" command to include "yield" kinds of things, I experimented with adding this in YARV.  (It's supposed to be there in rubinius.) Very quickly, I realized it would be easier, faster, reliable  and available to other programs such as your if I just changed YARV. So that's what I've now done.

If it causes problems, it can be removed. 

There are 3 new events. Yes 3!. There is a "send" event (which probably I may chuck) which is generally done before the call event. There is also yielding via "yield" and leaving a block which was yielded to called "leave". 

 

It's the difference between taking
off a hat and changing whole outfits.

> Furthermore, when I look at the patch in Redmine where you change the
> setting of that C local variable "tracing" I instinctively get nervous.
>  Your patch may be perfect, but I've had a lot of problems with changing
> that and it's cause obscure SEGV's in hard to reproduce situations in the
> debugger. To do a full job, one probably needs a lot more test cases than
> the one you have in the patch.

In this case I think the patch is just a band-aid for the underlying
brokenness of continuations. Even the most intensive multi-threaded
code has balanced PUSH_TAGs and POP_TAGs. But a simple continuation
example from the documentation produces more PUSH_TAGs than POP_TAGs.
Though I've not investigated in detail, it seems evident that this is
a bad thing. My patch just clears the flag which would have been
cleared had PUSH_TAG and POP_TAG been balanced (the code preceding a
POP_TAG is supposed to clear it, but that code is never executed).

Ok. So that's probably why I was having problems. If you come up with a patch to balance the PUSH_TAG and POP_TAG, it's possible some of the workaround hacks that I've added and don't really understand could be eliminated.  So let me know if you come up with a patch.

[Roger Pack]

(Since I'm sure Rocky will know about this, I was reluctant to stir

traffic on ruby-core.)

Is there a reason that there is no trace event for a block ending? It
would seem useful to know when a scope has vanished.

I think this is a bug?
http://redmine.ruby-lang.org/issues/show/3660