Bug #16383: TracePoint does not report calls to attribute reader methods

• Status: Closed
• Assignee: -
• Target version: -
• ruby -v: ruby 2.5.7p206 (2019-10-01 revision 67816) [x86_64-darwin19]
• Backport: 2.5: UNKNOWN, 2.6: UNKNOWN
• Tags: tracepoint, patch

[AndyMaleh (Andy Maleh)]

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

[jeremyevans0 (Jeremy Evans)]

• File tracepoint-attr-16383.patch tracepoint-attr-16383.patch added

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.

[mame (Yusuke Endoh)]

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

[ko1 (Koichi Sasada)]

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.

[ko1 (Koichi Sasada)]

• matz: good to have, but not a showstopper

[Eregon (Benoit Daloze)]

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.

[headius (Charles Nutter)]

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.

[AndyMaleh (Andy Maleh)]

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

[st0012 (Stan Lo)]

This may be a long shot, but would it be possible to make a c extension and apply a patch similar to this from a gem?

I also think the --debug flag mentioned by Charles is an excellent idea. If we can hide debugging features behind a flag, they'll be easier to implement and have a faster development cycle.

[jeremyevans0 (Jeremy Evans)]

After thinking more regarding this issue, if we want no overhead by default, and only overhead if this feature is enabled via a command line flag (similar to JRuby's --debug flag), one possibility is to just use BMETHOD (or ISEQ) methods instead of IVAR/ATTRSET methods for attributes. A proof of concept for this can be implemented by adding the following to the top of prelude.rb:

if $DEBUG
  class Module
    remove_method(:attr_accessor)
    def attr_accessor(*meths)
      attr_reader(*meths)
      attr_writer(*meths)
      meths
    end

    remove_method(:attr_reader)
    def attr_reader(*meths)
      module_exec do
        meths.each do |meth|
          instance_variable_get(:"@#{meth}") # check valid
          define_method(meth) do
            instance_variable_get(:"@#{meth}")
          end
        end
      end
      meths
    end

    remove_method(:attr_writer)
    def attr_writer(*meths)

      module_exec do
        meths.each do |meth|
          instance_variable_get(:"@#{meth}") # check valid
          define_method(:"#{meth}=") do |v|
            instance_variable_set(:"@#{meth}", v)
          end
        end
      end
      meths
    end
  end
end

Then you can run ruby with the --debug flag to enable tracing of attribute methods. As this approach uses BMETHOD instead of ISEQ, it needs the fix for #13392 to be committed for it to make sense.

This approach doesn't handle direct rb_attr use by C-extensions, though that could theoretically be fixed by making rb_attr use rb_funcall, at least for IDs that are valid instance variable names.

• Status changed from Open to Closed

Applied in changeset git|2d98593bf54a37397c6e4886ccc7e3654c2eaf85.

---

Support tracing of attr_reader and attr_writer

In vm_call_method_each_type, check for c_call and c_return events before
dispatching to vm_call_ivar and vm_call_attrset. With this approach, the
call cache will still dispatch directly to those functions, so this
change will only decrease performance for the first (uncached) call, and
even then, the performance decrease is very minimal.

This approach requires that we clear the call caches when tracing is
enabled or disabled. The approach currently switches all vm_call_ivar
and vm_call_attrset call caches to vm_call_general any time tracing is
enabled or disabled. So it could theoretically result in a slowdown for
code that constantly enables or disables tracing.

This approach does not handle targeted tracepoints, but from my testing,
c_call and c_return events are not supported for targeted tracepoints,
so that shouldn't matter.

This includes a benchmark showing the performance decrease is minimal
if detectable at all.

Fixes [Bug #16383]
Fixes [Bug #10470]

Co-authored-by: Takashi Kokubun [e-mail]

[Eregon (Benoit Daloze)]

• Related to Bug #18886: Struct aref and aset don't trigger any tracepoints. added