Bug #16889: TracePoint.enable { ... } also activates the TracePoint for other threads, even outside the block

• Status: Closed
• Assignee: ko1 (Koichi Sasada)
• Target version: -
• Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN

[Eregon (Benoit Daloze)]

threads = []
inspects = []
trace = TracePoint.new(:line) do |tp|
  threads << Thread.current
  inspects << tp.inspect
end

done = false
thread = Thread.new do
  Thread.pass until done
end

trace.enable do
  line_event = true
  done = true
  sleep 1
end
thread.join

# Expected only within enable block (lines 14-16)
puts inspects

# Expected just 1
p threads.uniq

Results in:

$ ruby tpbug.rb
ruby tpbug.rb
#<TracePoint:[e-mail]:14>
#<TracePoint:[e-mail]:15>
#<TracePoint:[e-mail]:16>
#<TracePoint:[e-mail]:10>
[#<Thread:0x00005571134e3340 run>, #<Thread:[e-mail]:9 dead>]

But I expected:

#<TracePoint:[e-mail]:14>
#<TracePoint:[e-mail]:15>
#<TracePoint:[e-mail]:16>
[#<Thread:0x00005571134e3340 run>]

Because the RDoc says:

If a block is given, the trace will only be enabled within the scope of
the block.

For background I'm trying to improve the TracePoint specs in ruby/spec, but they are proving quite unreliable due to this.

@ko1 (Koichi Sasada) Thoughts?

[Eregon (Benoit Daloze)]

• Description updated (diff)

[Eregon (Benoit Daloze)]

Maybe enable(&block) should behave like enable(target: block); disable?

[jeremyevans0 (Jeremy Evans)]

• Tracker changed from Bug to Feature
• ruby -v deleted (ruby 2.6.6p146 (2020-03-31 revision 67876) [x86_64-linux])
• Backport deleted (2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN)

Eregon (Benoit Daloze) wrote in #note-2:

Maybe enable(&block) should behave like enable(target: block); disable?

I looked into this. Implementing this fairly simple, but it breaks many tests and specs. The reason for this is that there are many tests and specs where this is not desired behavior, because they don't want to test tracing of the block itself, but tracing during the block.

Most of the breakage is actually that calling TracePoint#enable in a way that doesn't actually add any traces raises an error. Here's one such case, taken from test_tracepoint_thread:

    events = []
    thread_self = nil
    created_thread = nil
    TracePoint.new(:thread_begin, :thread_end){|tp|
      events << [Thread.current,
                 tp.event,
                 tp.lineno,  #=> 0
                 tp.path,    #=> nil
                 tp.binding, #=> nil
                 tp.defined_class, #=> nil,
                 tp.self.class # tp.self return creating/ending thread
                 ]
    }.enable{
      created_thread = Thread.new{thread_self = self}
      created_thread.join
    }
    events.reject!{|i| i[0] != created_thread}

Automatically making the block the target, similar to this code, results in an error:

    events = []
    thread_self = nil
    created_thread = nil
    block = proc{
      created_thread = Thread.new{thread_self = self}
      created_thread.join
    }
    TracePoint.new(:thread_begin, :thread_end){|tp|
      events << [Thread.current,
                 tp.event,
                 tp.lineno,  #=> 0
                 tp.path,    #=> nil
                 tp.binding, #=> nil
                 tp.defined_class, #=> nil,
                 tp.self.class # tp.self return creating/ending thread
                 ]
    }.enable(target: block, &block)
    # <internal:trace_point>:199:in `enable': can not enable any hooks (ArgumentError)

I'm guessing this is because :thread_begin and :thread_end events aren't triggered for code targets, unlike :line events.

Due to this issue, I don't think it makes sense to turn enable(&block) into enable(target: block); disable by default.

However, I think there value in making it nicer to enable only the targeting of the block. You can do this already, but it is clunky. In your example, you would do it like this:

threads = []
inspects = []
trace = TracePoint.new(:line) do |tp|
  threads << Thread.current
  inspects << tp.inspect
end

done = false
thread = Thread.new do
  Thread.pass until done
end

block = proc do
  line_event = true
  done = true
  sleep 1
end
trace.enable(target: block, &block)
thread.join

# Expected only within enable block (lines 14-16)
puts inspects

# Expected just 1
p threads.uniq

I propose we support target: :block to support using the block passed to enable as the target. This would enable the following API:

threads = []
inspects = []
trace = TracePoint.new(:line) do |tp|
  threads << Thread.current
  inspects << tp.inspect
end

done = false
thread = Thread.new do
  Thread.pass until done
end

trace.enable(target: :block) do
  line_event = true
  done = true
  sleep 1
end
thread.join

# Expected only within enable block (lines 14-16)
puts inspects

# Expected just 1
p threads.uniq

I've submitted a pull request that implements this: https://github.com/ruby/ruby/pull/4624.

[Eregon (Benoit Daloze)]

The reason for this is that there are many tests and specs where this is not desired behavior, because they don't want to test tracing of the block itself, but tracing during the block.

Right, I guess the expectation is that .enable { ... } also reports events from calls inside that block.
Maybe .enable { ... } should enable events only on that Thread (or better, Fiber) then?
That feels intuitive and I think is good enough for compatibility, what do you think?

[Eregon (Benoit Daloze)]

trace.enable(target: :block) seems nice to me (WDYT @ko1 (Koichi Sasada)?).

But I think trace.enable { ... } should not affect other Threads/Fiber, otherwise that form is just too confusing and error-prone.

[jeremyevans0 (Jeremy Evans)]

Eregon (Benoit Daloze) wrote in #note-5:

But I think trace.enable { ... } should not affect other Threads/Fiber, otherwise that form is just too confusing and error-prone.

If you look at the tests, they expect that enable is not limited to the current thread. The expected usage is tracing other threads during the duration of the block. You can already specify to only trace the current thread using: enable(target_thread: Thread.current). I do think enable only affecting the current thread may be a more common desire, but I can also see that enable allowing tracing other threads inside the block is also a reasonable use. I don't think it's worth breaking backwards compatibility to change the behavior.

[mame (Yusuke Endoh)]

TracePoint#enable(target: :block) does not follow events in a called method. Is this really intentional?

trace = TracePoint.new(:line) {|tp| p tp }

def foo
  1
end

trace.enable do
  foo
end
#=>
# #<TracePoint:line t.rb:8>
# #<TracePoint:line t.rb:4 in `foo'>

puts

trace.enable(target: :block) do
  foo
end
#=>
# #<TracePoint:line t.rb:17>

Note that the second trace.enable does not print #<TracePoint:line t.rb:4 in 'foo'>.

[ko1 (Koichi Sasada)]

+1 for Jeremy #6.

I also agree TP#enable{ ... } should be thread-local without any options, but I don't think it is valuable to change the default behaver (break compatibility).

[jeremyevans0 (Jeremy Evans)]

mame (Yusuke Endoh) wrote in #note-7:

TracePoint#enable(target: :block) does not follow events in a called method. Is this really intentional?

trace = TracePoint.new(:line) {|tp| p tp }

def foo
  1
end

trace.enable do
  foo
end
#=>
# #<TracePoint:line t.rb:8>
# #<TracePoint:line t.rb:4 in `foo'>

puts

trace.enable(target: :block) do
  foo
end
#=>
# #<TracePoint:line t.rb:17>

Note that the second trace.enable does not print #<TracePoint:line t.rb:4 in 'foo'>.

This matches the behavior of passing the block explicitly and using it as the target:

trace = TracePoint.new(:line) {|tp| p tp }

def foo
  1
end

trace.enable do
  foo
end
#=>
# #<TracePoint:line t.rb:8>
# #<TracePoint:line t.rb:4 in `foo'>

puts

pr = proc do
  foo
end

trace.enable(target: pr, &pr) 

#<TracePoint:line t.rb:17>

So I think it is expected. My guess would be while the location of the trace point shows the point of call, it isn't triggered unless the method itself is targeted. If you target both the method and the block, you get both lines:

trace = TracePoint.new(:line) {|tp| p tp }
trace2 = TracePoint.new(:line) {|tp| p tp }

def foo
  1
end

trace.enable do
  foo
end
#=>
# #<TracePoint:line t.rb:8>
# #<TracePoint:line t.rb:4 in `foo'>

puts

pr = proc do
  foo
end

trace2.enable(target: method(:foo)) do
  trace.enable(target: pr, &pr)
end
# #<TracePoint:line -:18>
# #<TracePoint:line -:5 in `foo'>

Whether the current behavior of targeted traces is a bug, I'm not sure. If so, it isn't a bug in the target: :block support, but a more general issue with targeted traces.

[Eregon (Benoit Daloze)]

mame (Yusuke Endoh) wrote in #note-7:

Note that the second trace.enable does not print #<TracePoint:line t.rb:4 in 'foo'>.

A very good point, that I thought about when talking a bit with Koichi about this, some time before filing this issue and then apparently forgot when filing the issue.

I do expect:

TracePoint.new(:line) {|tp| p tp }.enable do
  foo
end

to report lines within that last block, and within foo, so thread-local behavior in other words.
So I'd want tp.enable {} to be like tp.enable(target_thread: Thread.current) {}.

ko1 (Koichi Sasada) wrote in #note-8:

I also agree TP#enable{ ... } should be thread-local without any options, but I don't think it is valuable to change the default behaver (break compatibility).

Exactly. I think it could be worth it, because I think most people expect TP#enable {} to be thread local and not affect other threads which are executing in random places completely unrelated to the block.
The way I see it is enable { ... } should trace whatever is inside that block (including calls), but not other threads since they are not executing inside that block.
This is also why I filed it as a Bug, IMHO the current behavior is unexpected.

I guess the purpose of the current behavior is it behaves like open and so enable { ... } is like enable; ...; ensure; disable.
And maybe initially TracePoint did not support tracing a particular Thread?

I think it would be worth to experiment how little it would break to make tp.enable {} to be like tp.enable(target_thread: Thread.current) {}.
IMHO it would be worth changing, but I can also see others have compatibility concerns.
If someone actually wants to enable for all threads, they could anyway do tp.enable; ...; ensure; tp.disable, or tp.enable(target_thread: nil/:all/Thread.list).

If we keep the current behavior we should fix the docs, for me these docs clearly indicate thread-local behavior:

If a block is given, the trace will only be enabled within the scope of
the block.

  trace.enabled?
  #=> false

  trace.enable do
    trace.enabled?
    # only enabled for this block
  end

  trace.enabled?
  #=> false

i.e. "scope of the block" sounds like "events with this block call in the call stack" or "events within that block", but not the actual behavior "enable for all threads, and when quitting the block disable for all threads".

---

Regarding target: Proc I think it's clearly documented to only trace the Proc and no calls within it (rdoc of TracePoint#enable), so no objection to the behavior of enable(target:):

target, target_line and target_thread parameters are used to limit
tracing only to specified code objects. target should be a code object
for which RubyVM::InstructionSequence.of will return an instruction
sequence.

[Eregon (Benoit Daloze)]

Actually thread-local might not be enough, we'd probably want Fiber local, i.e., events which are on the same execution stack and contain that enable block call on the stack.
Is there any way to have a TracePoint for a particular Fiber?

[ko1 (Koichi Sasada)]

Eregon (Benoit Daloze) wrote in #note-11:

Actually thread-local might not be enough, we'd probably want Fiber local, i.e., events which are on the same execution stack and contain that enable block call on the stack.
Is there any way to have a TracePoint for a particular Fiber?

Just now, it is not provided.

[mame (Yusuke Endoh)]

Eregon (Benoit Daloze) wrote in #note-10:

I do expect:

TracePoint.new(:line) {|tp| p tp }.enable do
  foo
end

to report lines within that last block, and within foo, so thread-local behavior in other words.
So I'd want tp.enable {} to be like tp.enable(target_thread: Thread.current) {}.

Agreed. I think thread-local behavior is more reasonable. So, the current target: :block is not what you want, right?

Though I like thread-local behavior, I have some concerns:

• tp.enable { Thread.new { foo }.join } will not trace foo because it is run in another thread, but I'm unsure if this is expected.
• tp.enable called with no block should trace events in all threads, right? It is a bit inconsistent, but perhaps changing this to thread-local will break Zeitwerk.

[jeremyevans0 (Jeremy Evans)]

• Tracker changed from Feature to Bug
• Backport set to 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN

This was discussed at the August 2021 developer meeting, and it was decided that TracePoint#enable with a block will be thread-local by default. However, that change will not take place until after Ruby 3.1. I'm switching this back to bug.

[Eregon (Benoit Daloze)]

mame (Yusuke Endoh) wrote in #note-13:

Agreed. I think thread-local behavior is more reasonable. So, the current target: :block is not what you want, right?

Indeed. I'm not against it but I don't think it's necessary or so helpful.

Though I like thread-local behavior, I have some concerns:

• tp.enable { Thread.new { foo }.join } will not trace foo because it is run in another thread, but I'm unsure if this is expected.

I think it is expected. foo is not on the call stack of that tp.enable (it does have that TracePoint#enable as a caller).
With that logic I would also prefer if tp.enable { Fiber.new { foo }.resume } does not trace foo, but it is less important, as that could only happen if the enable blocks switches Fibers (probably rare).

Currently, Thread.new { sleep 1; foo }; tp.enable { bar } will trace bar (expected) but also foo (I find that unexpected/unintuitive).

• tp.enable called with no block should trace events in all threads, right? It is a bit inconsistent, but perhaps changing this to thread-local will break Zeitwerk.

Yes, tp.enable (no block) should trace events everywhere, I think that's intuitive, it doesn't provide any "target" or "context" (a block) so it's global.

[jeremyevans0 (Jeremy Evans)]

I submitted a pull request to make enable affect the current thread by default: https://github.com/ruby/ruby/pull/5359

The power_assert bundled gem tests fail with it, so power_assert will need to be updated before this can be merged. Just adding target_thread: nil to the enable calls does not appear to be enough to make power_assert work.

• Status changed from Open to Closed

Applied in changeset git|9c1d32a7ada794ecd0356d56f7be3cdf3982d8ac.

---

Make TracePoint#enable with block target current thread by default

If TracePoint#enable is passed a block, it previously started
the trace on all threads. This changes it to trace only the
current thread by default. To limit the scope of the change,
the current thread is only used by default if target and
target_line are both nil. You can pass target_thread: nil
to enable tracing on all threads, to get the previous
default behavior.

Fixes [Bug #16889]