Bug #14702: On Ruby 2.5.1, tracepoint isn't working on the file that is loaded by load_iseq

• Status: Closed
• Assignee: ko1 (Koichi Sasada)
• Target version: -
• ruby -v: ruby 2.5.1p57 (2018-03-29 revision 63029) [x86_64-darwin16]
• Backport: 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: DONE

[[e-mail] (Makoto Tajitsu)]

On Ruby 2.5.1, when loading file with RubyVM::InstructionSequence.load_from_binary, TracePoint callback event is not working on loaded file.

Steps to reproduce

Ruby version.

$ ruby -v
# => ruby 2.5.1p57 (2018-03-29 revision 63029) [x86_64-darwin16]

The example with yomikomu gem which is simply used load_iseq and load_from_binary method to load file quickly is following.

$ YOMIKOMU_AUTO_COMPILE=true bundle exec irb

> TracePoint.trace(:line) { |tp| puts tp.lineno if tp.path == '/path/to/somefile.rb' }
# => #<TracePoint:enabled>

> load '/path/to/somefile.rb'
# 3
# 4
# ...

> require 'yomikomu'

> load '/path/to/somefile.rb'
# no tracepoint callback for line event

Result of reproduce process

tracepoint callback isn't called on loaded file by using load_iseq and load_from_binary.

Expected result and the reason why you expect

tracepoint callback should be called for any loaded file to debug with debugguer(e.g. byebug).

On Ruby 2.4.3, this example is working correctly, so tracepoint callback is called and output lineno to stdout when loaded file after require 'yomikomu'.

[[e-mail] (Makoto Tajitsu)]

• Description updated (diff)

[[e-mail] (Makoto Tajitsu)]

• Description updated (diff)

[[e-mail] (Makoto Tajitsu)]

• Description updated (diff)

[[e-mail] (Makoto Tajitsu)]

• Description updated (diff)

How is the issue?

In addition to above, I confirm the issue in following example that does not use 3rd party gem.

#!/usr/bin/env ruby

# Write ruby file
File.write('./loaded_file.rb', 'puts :hello')

# load file and write iseq file
iseq = RubyVM::InstructionSequence.compile_file('./loaded_file.rb')
File.write('./loaded_file.yarb', iseq.to_binary)

# define load_iseq
class RubyVM::InstructionSequence
  def self.load_iseq(fname)
    b = File.read('./loaded_file.yarb')
    RubyVM::InstructionSequence.load_from_binary(b)
  end
end

TracePoint.trace(:line) do |tp|
  puts "file: #{tp.path}, line: #{tp.lineno}" if tp.path =~ /loaded_file/
end

load './loaded_file.rb' # => on ruby 2.5.0 and 2.5.1, no tracepoint callback is.

[ko1 (Koichi Sasada)]

• Assignee set to ko1 (Koichi Sasada)

[ko1 (Koichi Sasada)]

• Status changed from Open to Closed

Applied in changeset trunk|r64514.

---

check trace flags at loading [Bug #14702]

• iseq.c (iseq_init_trace): at ISeq loading time, we need to check
  ruby_vm_event_enabled_flags to turn on trace instructions.
  Seprate this checking code from finish_iseq_build() and make
  new function. iseq_ibf_load() calls this funcation after loading.

• test/ruby/test_iseq.rb: add a test for this fix.

[nagachika (Tomoyuki Chikanaga)]

• Backport changed from 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: UNKNOWN to 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: REQUIRED

[nagachika (Tomoyuki Chikanaga)]

• Backport changed from 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: REQUIRED to 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: DONE

ruby_2_5 r64997 merged revision(s) 64514.

[alanwu (Alan Wu)]

• File 0001-Fix-TracePoint-for-nested-iseq-loaded-from-binary.patch added

Hello. I don't think this issue is fully fixed.
I have put together a patch that has a fix and tests that fail on both trunk and ruby_2_5 for your consideration:

I've opened up a ticket for this patch: #15270

    Fix TracePoint for nested iseq loaded from binary [Bug #14702]
    
    When loading iseq from binary while a TracePoint is on, we need to
    recompile instructions to their "trace_" variant. Before this commit
    we only recompiled instructions in the top level iseq, which meant
    that TracePoint was malfunctioning for code inside module/class/method
    definitions.
    
    * compile.c: Move rb_iseq_init_trace to rb_ibf_load_iseq_complete.
      It is called on all iseqs during loading.
    
    * test_iseq.rb: Test that tracepoints fire within children iseq when
      using load_from_binary.

[alanwu (Alan Wu)]

• File deleted (0001-Fix-TracePoint-for-nested-iseq-loaded-from-binary.patch)

[fxn (Xavier Noria)]

Hi!

Rails 6 applcations have bootsnap and Zeitwerk enabled by default. Right now, that needs Ruby 2.6 because Zeitwerk sets a trace point on the :class event to support what I call "explicit namespaces".

Just wanted to let you know about this situation, in case you'd like to take it into account for the timeline to ship 2.5.4.

[fxn (Xavier Noria)]

For reference: https://github.com/rails/rails/issues/35475.