Bug #10470: TracePoint cannot trace attr_accessor/reader/writer method

• Status: Closed
• Assignee: ko1 (Koichi Sasada)
• Target version: -
• ruby -v: ruby 2.2.0dev (2014-11-01 trunk 48219) [x86_64-darwin13]
• Backport: 2.0.0: REQUIRED, 2.1: REQUIRED
• Tags: tracepoint

[joker1007 (Tomohiro Hashidate)]

TracePointを利用してattr_accessorで定義したメソッドの:c_call, :c_returnイベントを取得することができません。

class Foo
  attr_accessor :hoge

  def bar
    @bar
  end

  def initialize(val)
    @bar = val
  end
end

foo = Foo.new("FOO")

trace = TracePoint.new(:return, :c_return) do |tp|
  p [tp.lineno, tp.defined_class, tp.method_id, tp.event, tp.binding, tp.return_value]
end

trace.enable do
  foo.bar
  foo.hoge = "hoge"
  foo.hoge
end

上記のコードを実行した時、attr_accessorで定義したhogeメソッドのイベントが発生しません。
調査した所、EXEC_EVENT_HOOKの呼び出し自体が無いようです。
このため、例えばpower_assertを利用した時にアクセサメソッドの戻り値を取得できない等の問題が発生します。

attributeの読み書きを行う処理の中にEXEC_EVENT_HOOKを呼び出す簡単なパッチを書きましたので、添付します。

[nobu (Nobuyoshi Nakada)]

• Description updated (diff)
• Category set to core
• Status changed from Open to Assigned
• Assignee set to ko1 (Koichi Sasada)
• Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN to 2.0.0: REQUIRED, 2.1: REQUIRED

[ko1 (Koichi Sasada)]

遅くなりました。

こちら、性能劣化をいやがって、このような仕様にしているところがあります。
同じようなものに、Fixnum 同士の足し算などがあります。

まつもとさんからは、「出来るようにして欲しい」というリクエストを頂いているので、対応したものだか悩んでいるところです。

どなたか、ご協力頂けないでしょうか。
(1) 性能測定
(2) 何か性能劣化がない形で提供する方法はないか

[joker1007 (Tomohiro Hashidate)]

添付したパッチと同じ様にEXEC_EVENT_HOOKを追加して性能測定をしてみました。
測定にはbenchmark-ipsというgemを使って、100msでの実行命令数を計測しています。
測定に使ったソースコードは以下の通りです。

require 'benchmark/ips'

class Foo
  attr_accessor :hoge

  def bar
    @bar
  end

  def initialize(val)
    @bar = val
  end
end

foo = Foo.new("FOO")

trace = TracePoint.new(:return, :c_return) do |tp|
  [tp.lineno, tp.defined_class, tp.method_id, tp.event, tp.binding, tp.return_value]
end


Benchmark.ips do |x|
  x.report("tracing access") do |time|
    trace.enable do
      foo.bar
      foo.hoge = "hoge#{time}"
      foo.hoge
    end
  end
end

結果

トレースを実行している場合としていない場合、EXEC_EVENT_HOOK有の場合と無しの場合の組み合わせで実行しています。

trace.enable, EXEC_EVENT_HOOK無し

Calculating -------------------------------------
      tracing access    25.401k i/100ms
-------------------------------------------------
      tracing access      8.873B (±26.2%) i/s -     25.151B

trace.enable, EXEC_EVENT_HOOK有り

Calculating -------------------------------------
      tracing access    18.765k i/100ms
-------------------------------------------------
      tracing access      4.404B (±26.9%) i/s -     12.809B

trace無し, EXEC_EVENT_HOOK無し

Calculating -------------------------------------
      tracing access   108.694k i/100ms
-------------------------------------------------
      tracing access    108.487B (±18.8%) i/s -    187.556B

trace無し, EXEC_EVENT_HOOK有り

Calculating -------------------------------------
      tracing access   104.899k i/100ms
-------------------------------------------------
      tracing access    104.985B (±18.4%) i/s -    183.617B

トレースを実行している場合は倍程度パフォーマンスに差があります。
トレースをしていない場合にも、2,3%程度性能劣化してる感じです。

[joker1007 (Tomohiro Hashidate)]

すいません。
元のサンプルコードを流用してしまったので、tracepointの性能測定としては余り適切じゃない感じのコードになってたことに気付きました。

trace = TracePoint.new(:return, :c_return) do |tp|
  [tp.lineno, tp.defined_class, tp.method_id, tp.event, tp.binding, tp.return_value]
end

をもっとシンプルな形に変えて検証してみた場合、倍もパフォーマンスに違いは出ませんでした。
EXEC_EVENT_HOOKが無い場合はtp.binding等がそもそも呼ばれていないのでbindingを作る負荷が大分上乗せされてました…。
修正版とその結果を貼っておきます。
これでもEXEC_EVENT_HOOKがある場合は無い場合と比べてアクセサメソッド分のTracePointのインスタンスが生成されるのでその分の負荷が上乗せされることになります。

require 'benchmark/ips'

class Foo
  attr_accessor :hoge

  def bar
    @bar
  end

  def initialize(val)
    @bar = val
  end
end

foo = Foo.new("FOO")

trace = TracePoint.new(:return, :c_return) do |tp|
  tp
end


Benchmark.ips do |x|
  x.report("tracing access") do |time|
    trace.enable do
      foo.bar
      foo.hoge = "hoge#{time}"
      foo.hoge
    end
  end
end

trace.enable EXEC_EVENT_HOOK無し

Calculating -------------------------------------
      tracing access    59.598k i/100ms
-------------------------------------------------
      tracing access     47.489B (±36.5%) i/s -    103.366B

trace.enable EXEC_EVENT_HOOK有り

Calculating -------------------------------------
      tracing access    55.833k i/100ms
-------------------------------------------------
      tracing access     39.855B (±41.0%) i/s -     87.620B

[ko1 (Koichi Sasada)]

こちら、随分間をあけてしまって申し訳ありません。

気になるのは、

• 「hook を出来ない状態にして（つまり、現状）、disable のまま実行」
• 「hook を出来る状態にして、disable のまま実行」

の比較なのですが（つまり、enable で遅くなるのは、まぁ気にしない）、こちらお願い出来ますでしょうか。

あと、attr だけでいいんかな。

[mame (Yusuke Endoh)]

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

• Status changed from Assigned 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]