Bug #16889
closed
TracePoint.enable { ... } also activates the TracePoint for other threads, even outside the block
Added by Eregon (Benoit Daloze) over 5 years ago. Updated over 3 years ago.
Description
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:line@tpbug.rb:14> #<TracePoint:line@tpbug.rb:15> #<TracePoint:line@tpbug.rb:16> #<TracePoint:line@tpbug.rb:10> [#<Thread:0x00005571134e3340 run>, #<Thread:0x00005571138ac828@tpbug.rb:9 dead>] But I expected:
#<TracePoint:line@tpbug.rb:14> #<TracePoint:line@tpbug.rb:15> #<TracePoint:line@tpbug.rb: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?
Updated by Eregon (Benoit Daloze) over 5 years ago Actions #1
- Description updated (diff)
Updated by Eregon (Benoit Daloze) over 5 years ago Actions #2 [ruby-core:98356]
Maybe enable(&block) should behave like enable(target: block); disable?
Updated by jeremyevans0 (Jeremy Evans) over 4 years ago Actions #3 [ruby-core:104478]
- 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 likeenable(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.
Updated by Eregon (Benoit Daloze) over 4 years ago Actions #4
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?
Updated by Eregon (Benoit Daloze) over 4 years ago Actions #5 [ruby-core:104505]
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.
Updated by jeremyevans0 (Jeremy Evans) over 4 years ago Actions #6 [ruby-core:104507]
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.
Updated by mame (Yusuke Endoh) about 4 years ago Actions #7 [ruby-core:104937]
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'>.
Updated by ko1 (Koichi Sasada) about 4 years ago Actions #8 [ruby-core:104938]
+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).
Updated by jeremyevans0 (Jeremy Evans) about 4 years ago Actions #9 [ruby-core:104939]
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.enabledoes 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.
Updated by Eregon (Benoit Daloze) about 4 years ago Actions #10 [ruby-core:104948]
mame (Yusuke Endoh) wrote in #note-7:
Note that the second
trace.enabledoes 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.
Updated by Eregon (Benoit Daloze) about 4 years ago Actions #11 [ruby-core:104950]
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?
Updated by ko1 (Koichi Sasada) about 4 years ago Actions #12 [ruby-core:104995]
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.
Updated by mame (Yusuke Endoh) about 4 years ago Actions #13 [ruby-core:105020]
Eregon (Benoit Daloze) wrote in #note-10:
I do expect:
TracePoint.new(:line) {|tp| p tp }.enable do foo endto report lines within that last block, and within
foo, so thread-local behavior in other words.
So I'd wanttp.enable {}to be liketp.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 tracefoobecause it is run in another thread, but I'm unsure if this is expected. -
tp.enablecalled 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.
Updated by jeremyevans0 (Jeremy Evans) about 4 years ago Actions #14 [ruby-core:105027]
- 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.
Updated by Eregon (Benoit Daloze) about 4 years ago Actions #15 [ruby-core:105031]
mame (Yusuke Endoh) wrote in #note-13:
Agreed. I think thread-local behavior is more reasonable. So, the current
target: :blockis 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 tracefoobecause 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.enablecalled 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.
Updated by jeremyevans0 (Jeremy Evans) almost 4 years ago Actions #16 [ruby-core:106852]
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.
Updated by jeremyevans (Jeremy Evans) over 3 years ago Actions #17
- 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]