Bug #10470
closedTracePoint cannot trace attr_accessor/reader/writer method
Description
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
を呼び出す簡単なパッチを書きましたので、添付します。
Files
Updated by nobu (Nobuyoshi Nakada) about 10 years ago
- 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
Updated by ko1 (Koichi Sasada) about 10 years ago
遅くなりました。
こちら、性能劣化をいやがって、このような仕様にしているところがあります。
同じようなものに、Fixnum 同士の足し算などがあります。
まつもとさんからは、「出来るようにして欲しい」というリクエストを頂いているので、対応したものだか悩んでいるところです。
どなたか、ご協力頂けないでしょうか。
(1) 性能測定
(2) 何か性能劣化がない形で提供する方法はないか
Updated by joker1007 (Tomohiro Hashidate) almost 10 years ago
添付したパッチと同じ様に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%程度性能劣化してる感じです。
Updated by joker1007 (Tomohiro Hashidate) almost 10 years ago
すいません。
元のサンプルコードを流用してしまったので、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
Updated by ko1 (Koichi Sasada) over 9 years ago
こちら、随分間をあけてしまって申し訳ありません。
気になるのは、
- 「hook を出来ない状態にして(つまり、現状)、disable のまま実行」
- 「hook を出来る状態にして、disable のまま実行」
の比較なのですが(つまり、enable で遅くなるのは、まぁ気にしない)、こちらお願い出来ますでしょうか。
あと、attr だけでいいんかな。
Updated by mame (Yusuke Endoh) almost 5 years ago
- Related to Bug #16383: TracePoint does not report calls to attribute reader methods added
Updated by jeremyevans (Jeremy Evans) over 3 years ago
- 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 takashikkbn@gmail.com