Issue #20299 has been updated by kjtsanaktsidis (KJ Tsanaktsidis).
Hm. I see. Thanks for the report.
The problem is the following sequence of operations:
* `tp.enable` - This attaches a global event handler to fire the tracepoint for all
threads
* `tp.enable { ...` - When the block begins, it sets `target_th` on the tracepoint, but
does not actually attach a thread-local handler, since a global handler is already set
* ` ... }` - When the block ends, `rb_tracepoint_enable` is called again, since the
tracepoint was already enabled, but that does nothing.
* `tp.disable` - This sees that `target_th` is set, so tries to detach a thread-local
event handler for the tracepoint. But, there _is_ no thread local handler, so nothing
happens! However, it does have the effect of clearing `target_th`
* `tp.disable` - Now that `target_th` is set, it tries to detach the global event
handler, not the thread local one, so it succeeds.
I'm not 100% sure what should happen here. We could make sure that `tracepoint.enable
{ ... }` does not actually set `target_th` if we're already tracing? That would make
it a no-op, but it would have the somewhat surprising effect of causing this to happen:
```
trace = TracePoint.new(:line) {}
puts trace.enabled? # true
trace.enable do
puts trace.enabled? # true
trace.disable
puts trace.enabled? # false
end
puts trace.enabled? # true, because the end of the enable block resets the state to how it
was before.
```
Honestly I'm strugling to think of what sensible scenario there even is for mixing the
block & non-block forms of `enable` on the same tracepoint, and I think that perhaps
doing so should simply raise an argument error (like your second example does).
----------------------------------------
Bug #20299: Tracepoint staying enable after a disable
https://bugs.ruby-lang.org/issues/20299#change-107190
* Author: MaxLap (Maxime Lapointe)
* Status: Open
* ruby -v: 3.3.0
* Backport: 3.0: UNKNOWN, 3.1: UNKNOWN, 3.2: UNKNOWN, 3.3: UNKNOWN
----------------------------------------
Problem is present in Ruby 3.2.2, 3.2.3, 3.3.0. Didn't check before.
It seems that TracePoint can sometime be "stuck" enabled after using disabled
once on it.
Here is a reproduction step using a "check speed" method that just does some
work and print out how long it takes. This makes it pretty clear when TracePoint was on.
Put this in a Ruby file:
```
def check_speed(msg)
t1 = Time.now.to_f
a = 0
1000000.times { |i|
a += 10
}
t2 = Time.now.to_f
puts "#{t2-t1} - #{msg}"
end
check_speed("before") # fast
trace = TracePoint.new(:line) {}
trace.enable
check_speed("after enable") # slow
trace.enable {
check_speed("in block enable") # slow
}
check_speed("after block enable") # slow
trace.disable
check_speed("after disable") # slow !!!!
trace.disable
check_speed("after disable again") # fast !!!!
# And yet, using enable multiple time doesn't have a "counter" or similar
trace.enable
trace.enable
trace.enable
check_speed("after triple enable") # slow
trace.disable
check_speed("after single disable") # fast
```
Running the file, we get this:
```
$ ruby -v
ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [x86_64-linux]
$ ruby local.rb
0.03473854064941406 - before
0.18935227394104004 - after enable
0.17757630348205566 - in block enable
0.18320131301879883 - after block enable
0.1818866729736328 - after disable
0.03412747383117676 - after disable again
0.18405628204345703 - after triple enable
0.033496856689453125 - after single disable
```
The first "after disable" should probably have been fast. If it's possible
to have multiple nested enable/disable, then one would instead assume that after the last
"single disable", things would still be slow.
Note: This code patterns comes directly for a ruby/spec: ctrl+f for "enables trace
object on calling with a block if it was already enabled"
I note that in Ruby 3.2, the timing are a lot less similar. I don't know why. It would
seem like TracePoint got slower in Ruby 3.3.0. Is that worth checking out / making a
distincct bug for?
```
$ rvm use 3.2.3
Using /home/max/.rvm/gems/ruby-3.2.3
$ ruby local.rb
0.03246927261352539 - before
0.07910513877868652 - after enable
0.10309600830078125 - in block enable
0.12397646903991699 - after block enable
0.07114601135253906 - after disable
0.028218746185302734 - after disable again
0.12534689903259277 - after triple enable
0.02810525894165039 - after single disable
```
--
https://bugs.ruby-lang.org/