Project

General

Profile

Bug #16383

TracePoint does not report calls to attribute reader methods

Added by AndyMaleh (Andy Maleh) about 2 months ago. Updated 7 days ago.

Status:
Open
Priority:
Normal
Assignee:
-
Target version:
-
ruby -v:
ruby 2.5.7p206 (2019-10-01 revision 67816) [x86_64-darwin19]
[ruby-core:96032]

Description

TracePoint does not report calls to attribute reader methods (e.g. methods defined using attr_accessor or attr_reader.)

Code sample to demonstrate:

class Person
  attr_accessor :first_name
  attr_accessor :last_name
  def name
    "#{self.last_name}, #{self.first_name}"
  end
end

person = Person.new
person.first_name = 'Josh'
person.last_name = 'McGibbon'
trace = TracePoint.new(:call) do |tp|
  p [tp.path, tp.lineno, tp.defined_class, tp.event, tp.method_id]
end
trace.enable
person.name
trace.disable

class Person
  attr_writer :first_name
  attr_writer :last_name
  def name
    "#{self.last_name}, #{self.first_name}"
  end
  def first_name
    @first_name
  end
  def last_name
    @last_name
  end
end

person = Person.new
person.first_name = 'Josh'
person.last_name = 'McGibbon'
trace = TracePoint.new(:call) do |tp|
  p [tp.path, tp.lineno, tp.defined_class, tp.event, tp.method_id]
end
trace.enable
person.name
trace.disable

Output:

["trace_point_issue.rb", 4, Person, :call, :name]
["trace_point_issue.rb", 22, Person, :call, :name]
["trace_point_issue.rb", 28, Person, :call, :last_name]
["trace_point_issue.rb", 25, Person, :call, :first_name]

Please note how :last_name and :first_name show up only the second time Person#name is called. In other words, they show up when defined as actual methods using def keyword, but not when defined via attr_accessor.

Expected Output:

["trace_point_issue.rb", 22, Person, :call, :name]
["trace_point_issue.rb", 28, Person, :call, :last_name]
["trace_point_issue.rb", 25, Person, :call, :first_name]
["trace_point_issue.rb", 22, Person, :call, :name]
["trace_point_issue.rb", 28, Person, :call, :last_name]
["trace_point_issue.rb", 25, Person, :call, :first_name]

Your help in fixing or explaining this issue is greatly appreciated.

My goal is to monitor all method calls when invoking a certain method (Person#name in this case) in order to attach observers to them dynamically for desktop UI data-binding use in my open-source project Glimmer: https://github.com/AndyObtiva/glimmer

Cheers,

Andy Maleh


Files

trace_point_issue.rb (791 Bytes) trace_point_issue.rb contains code sample to demonstrate issue AndyMaleh (Andy Maleh), 11/30/2019 03:16 AM
tracepoint-attr-16383.patch (1.97 KB) tracepoint-attr-16383.patch jeremyevans0 (Jeremy Evans), 12/04/2019 12:42 AM

Related issues

Related to Ruby master - Bug #10470: TracePoint cannot trace attr_accessor/reader/writer methodAssignedActions

History

Updated by jeremyevans0 (Jeremy Evans) about 2 months ago

I'm not sure if skipping tracing for these methods is on purpose for performance reasons or not, but I agree it would be useful to be able to trace such method calls. Attached is a patch that implements tracing for attr_reader/attr_writer method calls. I'm not sure it is correct, but with the following code:

class Person
  attr_accessor :first_name
  attr_accessor :last_name
  def name
    "#{self.last_name}, #{self.first_name}"
  end
end

person = Person.new
trace = TracePoint.new(:c_call, :call) do |tp|
  p [tp.path, tp.lineno, tp.defined_class, tp.event, tp.callee_id]
end
trace.enable
person.first_name = 'Josh'
person.last_name = 'McGibbon'
person.name
trace.disable

I get the following output:

["t.rb", 14, Person, :c_call, :first_name=]
["t.rb", 15, Person, :c_call, :last_name=]
["t.rb", 4, Person, :call, :name]
["t.rb", 5, Person, :c_call, :last_name]
["t.rb", 5, Person, :c_call, :first_name]
["<internal:trace_point>", 231, TracePoint, :call, :disable]

Note that because attr_reader/attr_writer are implemented in C, I choose :c_call and :c_return instead of :call and :return. There is at least a bug in that method_id is incorrect, showing the instance variable symbol instead of the method symbol.

#2

Updated by mame (Yusuke Endoh) 9 days ago

  • Related to Bug #10470: TracePoint cannot trace attr_accessor/reader/writer method added

Updated by ko1 (Koichi Sasada) 8 days ago

miniruby.modif is patch applied version.

Benchmark.driver(repeat_count: 10){|x|
  x.executable name: 'clean', command: %w'./miniruby'
  x.executable name: 'modif', command: %w'./miniruby.modif'

  x.prelude %q{
    class C
      attr_reader :x
      def initialize
        @x = nil
      end
    end
    obj = C.new
  }
  x.report 'obj.x*64', "obj.x; " * 64
}

Warming up --------------------------------------
            obj.x*64     1.697M i/s -      1.712M times in 1.008554s (589.26ns/i)
Calculating -------------------------------------
                          clean       modif
            obj.x*64     1.773M      1.364M i/s -      5.091M times in 2.870868s 3.731838s

Comparison:
                         obj.x*64
               clean:   1773371.7 i/s
               modif:   1364238.2 i/s - 1.30x  slower

On microbenchmark, it is 30% slower, so we need to invent a hack to support it.

Updated by ko1 (Koichi Sasada) 7 days ago

  • matz: good to have, but not a showstopper

Also available in: Atom PDF