Bug #20299: Tracepoint staying enable after a disable

• Status: Open
• Assignee: -
• Target version: -
• ruby -v: 3.3.0
• Backport: 3.0: UNKNOWN, 3.1: UNKNOWN, 3.2: UNKNOWN, 3.3: UNKNOWN

[MaxLap (Maxime Lapointe)]

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

[MaxLap (Maxime Lapointe)]

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"

[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).