Project

General

Profile

Bug #16383

TracePoint does not report calls to attribute reader methods

Added by AndyMaleh (Andy Maleh) 4 months ago. Updated 26 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 methodAssignedko1 (Koichi Sasada)Actions

Updated by jeremyevans0 (Jeremy Evans) 4 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) 3 months ago

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

Updated by ko1 (Koichi Sasada) 3 months 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) 3 months ago

  • matz: good to have, but not a showstopper

Updated by Eregon (Benoit Daloze) 26 days ago

Are there plans to implement this in master, any timeline?

Andy Maleh wants to add specs for this in https://github.com/ruby/spec/pull/761 which is nice but we would need an expected fix version.

Updated by headius (Charles Nutter) 26 days ago

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

In JRuby, that hack is called the --debug flag, which enables the full set of traces. At some point CRuby's probably going to have to do something similar, or else every operation in Ruby's going to pay the price of traces whether they're used or not.

Also available in: Atom PDF