Project

General

Profile

Bug #16383

TracePoint does not report calls to attribute reader methods

Added by AndyMaleh (Andy Maleh) about 1 year ago. Updated 2 months 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) about 1 year 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) about 1 year ago

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

Updated by ko1 (Koichi Sasada) about 1 year 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) about 1 year ago

  • matz: good to have, but not a showstopper

Updated by Eregon (Benoit Daloze) 12 months 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) 12 months 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.

Updated by AndyMaleh (Andy Maleh) 2 months ago

Hi,

I compensated for lack of this feature by implementing manually-configured computed data-binding in Glimmer DSL for Tk (Ruby Desktop Development GUI Library), Glimmer DSL for SWT (JRuby Desktop Development GUI Library), and Glimmer DSL for Opal (Pure Ruby Web GUI and Auto-Webifier of Desktop Apps via Opal on Rails).

Example:

 label {
   text bind(@contact, :name, computed_by: [:first_name, :last_name])
 }

Alternatively, the #first_name and #last_name attributes could be implemented in the model as methods that notify observers of #name that it changed when called.

Still, I'd like to go a step further and implement automatic computed data-binding with simpler syntax:

 label {
   text bind(@contact, :name)
 }

That way, Glimmer could automatically figure out through calling the Contact#name method that it calls the first_name and last_name attributes, and then hook observers to them for change notifications to update the GUI.

I was wondering if there is any chance to have this missing feature (tracing attribute calls) supported in Ruby 3.0 via an extra ruby command option (e.g. --trace-func) as per Charles Nutter's suggestion to avoid slowing down general app performance when this feature is not needed. Perhaps even make it configurable (e.g. --trace-func=attr_accessor for attribute-tracing only, or a comma separated list like --trace-func=methods,attr_reader) to ensure further that the performance hit is limited when the feature is needed.

I realize this feature (automatic computed data-binding) is very new and has not been proven as feasible for practical application development, but I have not seen it implemented anywhere else (e.g. Java/JavaScript) with this level of automation (knowing which variables to observe without manual configuration), and I believe Ruby is the language to make that happen if any, so I'd really like to give it a go.

Cheers,

Andy Maleh

Also available in: Atom PDF