Bug #20299
openTracepoint staying enable after a disable
Description
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
Updated by MaxLap (Maxime Lapointe) 8 months ago
And here is a similar problem, using only the block form (no calls to disable):
def check_speed(msg = nil)
t1 = Time.now.to_f
a = 0
1000000.times { |i|
a += 10
}
t2 = Time.now.to_f
puts "#{t2-t1} - #{msg}"
end
trace = TracePoint.new(:line) {}
check_speed("a") # fast
begin
trace.enable do
check_speed("b") # slow
trace.enable(target: -> {}) do
end
end
rescue => e
end
check_speed("c") # slow !!!!
Results in (Ruby 3.3.0 for clearer distinction):
$ ruby local2.rb
0.034399986267089844 - a
0.1835155487060547 - b
0.1803114414215088 - c
Note: This code pattern also comes from ruby/spec: search for "raises ArgumentError if trace point already enabled without target is re-enabled with target"
Updated by kjtsanaktsidis (KJ Tsanaktsidis) 8 months ago
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 setstarget_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 thattarget_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 clearingtarget_th
-
tp.disable
- Now thattarget_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).