Issue #20299 has been updated by 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" ---------------------------------------- Bug #20299: Tracepoint staying enable after a disable https://bugs.ruby-lang.org/issues/20299#change-106983 * 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/