https://bugs.ruby-lang.org/https://bugs.ruby-lang.org/favicon.ico?17113305112013-03-12T03:17:01ZRuby Issue Tracking SystemRuby master - Bug #7976: TracePoint call is at call point, not call sitehttps://bugs.ruby-lang.org/issues/7976?journal_id=375172013-03-12T03:17:01Ztenderlovemaking (Aaron Patterson)tenderlove@ruby-lang.org
<ul><li><strong>Category</strong> changed from <i>YARV</i> to <i>core</i></li></ul> Ruby master - Bug #7976: TracePoint call is at call point, not call sitehttps://bugs.ruby-lang.org/issues/7976?journal_id=402052013-06-30T21:26:33Zdeivid (David RodrÃguez)
<ul></ul><p>I find this behaviour satisfactory for my purposes.</p>
<p>If I need the origin of a :call event I use the previous :line event. Is this wrong?</p> Ruby master - Bug #7976: TracePoint call is at call point, not call sitehttps://bugs.ruby-lang.org/issues/7976?journal_id=421002013-09-30T20:27:17Zko1 (Koichi Sasada)
<ul><li><strong>Target version</strong> set to <i>2.1.0</i></li></ul> Ruby master - Bug #7976: TracePoint call is at call point, not call sitehttps://bugs.ruby-lang.org/issues/7976?journal_id=424102013-10-10T18:06:43Zko1 (Koichi Sasada)
<ul><li><strong>Status</strong> changed from <i>Open</i> to <i>Feedback</i></li></ul><p>This behavior is same as backtrace.<br>
Nearest file name and line number is used for C call,<br>
because there are no file name and line for C methods.</p>
<pre><code># modify trace as follows:
tp = TracePoint.new(:call, :return, :c_call, :c_return, :raise) do |t|
p caller(1, 1)[0].inspect + ("%-9p %s:%02d %p" % [t.event, t.path, t.lineno, t.method_id])
end
#=>
ruby 2.1.0dev (2013-10-10 trunk 43236) [i386-mswin32_110]
"\"tp_test.rb:5:in `<main>'\":c_return tp_test.rb:05 :enable"
"\"tp_test.rb:7:in `<main>'\":c_call tp_test.rb:07 :inherited"
"\"tp_test.rb:7:in `<main>'\":c_return tp_test.rb:07 :inherited"
"\"tp_test.rb:8:in `<class:X>'\":c_call tp_test.rb:08 :method_added"
"\"tp_test.rb:8:in `<class:X>'\":c_return tp_test.rb:08 :method_added"
"\"tp_test.rb:12:in `<class:X>'\":c_call tp_test.rb:12 :method_added"
"\"tp_test.rb:12:in `<class:X>'\":c_return tp_test.rb:12 :method_added"
"\"tp_test.rb:16:in `<class:X>'\":c_call tp_test.rb:16 :method_added"
"\"tp_test.rb:16:in `<class:X>'\":c_return tp_test.rb:16 :method_added"
"\"tp_test.rb:21:in `<main>'\":c_call tp_test.rb:21 :new"
"\"tp_test.rb:21:in `new'\":c_call tp_test.rb:21 :initialize"
"\"tp_test.rb:21:in `new'\":c_return tp_test.rb:21 :initialize"
"\"tp_test.rb:21:in `<main>'\":c_return tp_test.rb:21 :new"
"\"tp_test.rb:8:in `x'\":call tp_test.rb:08 :x"
"\"tp_test.rb:12:in `y'\":call tp_test.rb:12 :y"
"\"tp_test.rb:16:in `z'\":call tp_test.rb:16 :z"
"\"tp_test.rb:17:in `z'\":c_call tp_test.rb:17 :raise"
"\"tp_test.rb:17:in `raise'\":c_call tp_test.rb:17 :new"
"\"tp_test.rb:17:in `new'\":c_call tp_test.rb:17 :initialize"
"\"tp_test.rb:17:in `new'\":c_return tp_test.rb:17 :initialize"
"\"tp_test.rb:17:in `raise'\":c_return tp_test.rb:17 :new"
"\"tp_test.rb:17:in `z'\":c_call tp_test.rb:17 :backtrace"
"\"tp_test.rb:17:in `z'\":c_return tp_test.rb:17 :backtrace"
"\"tp_test.rb:17:in `z'\":raise tp_test.rb:17 :z"
"\"tp_test.rb:17:in `z'\":c_return tp_test.rb:17 :raise"
"\"tp_test.rb:17:in `z'\":return tp_test.rb:17 :z"
"\"tp_test.rb:13:in `y'\":return tp_test.rb:13 :y"
"\"tp_test.rb:9:in `x'\":return tp_test.rb:09 :x"
tp_test.rb:17:in `z': no (RuntimeError)
from tp_test.rb:13:in `y'
from tp_test.rb:9:in `x'
from tp_test.rb:21:in `<main>'
</code></pre>
<p>And binding is also nearest Ruby level binding.</p>
<pre><code> tp = TracePoint.trace(:call, :return, :c_call, :c_return, :raise) do |t|
p [t, t.self, t.binding.eval('self')]
end
tp.enable
#=>
ruby 2.1.0dev (2013-10-10 trunk 43236) [i386-mswin32_110]
[#<TracePoint:c_return `trace'@tp_test.rb:1>, TracePoint, main]
[#<TracePoint:c_call `enable'@tp_test.rb:5>, #<TracePoint:c_call `enable'@tp_test.rb:5>, main]
[#<TracePoint:c_return `enable'@tp_test.rb:5>, #<TracePoint:c_return `enable'@tp_test.rb:5>, main]
[#<TracePoint:c_return `enable'@tp_test.rb:5>, #<TracePoint:c_return `enable'@tp_test.rb:5>, main]
[#<TracePoint:c_call `times'@tp_test.rb:7>, 1, main]
[#<TracePoint:c_call `times'@tp_test.rb:7>, 1, main]
[#<TracePoint:c_return `times'@tp_test.rb:7>, 1, main]
[#<TracePoint:c_return `times'@tp_test.rb:7>, 1, main]
</code></pre>
<p>self of <code>times' method is </code>1'. However, binding.eval('self') returns main. This means that binding is also used Ruby level.<br>
This is limitation of current TracePoint.</p>
<p>What should be happen on such case?</p> Ruby master - Bug #7976: TracePoint call is at call point, not call sitehttps://bugs.ruby-lang.org/issues/7976?journal_id=447622014-01-30T06:16:48Zhsbt (Hiroshi SHIBATA)hsbt@ruby-lang.org
<ul><li><strong>Target version</strong> changed from <i>2.1.0</i> to <i>2.2.0</i></li></ul> Ruby master - Bug #7976: TracePoint call is at call point, not call sitehttps://bugs.ruby-lang.org/issues/7976?journal_id=633082017-03-02T14:56:20Zjahfer (Jahfer Husain)
<ul></ul><p>I recently found this behaviour while attempting to build a gem that outputs the full call graph for our Rails application.</p>
<p>Using TracePoint, we can capture all calls/returns with the object the method is invoked upon, but finding the actual site of the invocation is a daunting task. My gem is a C-extension, and after much experimentation, the only reliable way to get the correct caller is through using <code>caller_locations</code>, which computes the full backtrace from the VM and is a significant slowdown when compared to using <code>rb_tracearg_path</code>.</p>
<p>As a point of comparison, we can run 63k tests (parallelized) while invoking <code>rb_tracearg_path</code> in roughly 10 minutes, whereas using <code>caller_locations</code> takes about 1.5 hours to complete.</p>
<p>Regardless of how the file paths are computed, their accuracy is significant for the performance of our gem because we are able to use a blacklist to ignore logging all gem method invocations as well as Rails core or other infrastructural pieces that we do not need to trace.</p>
<p>I also attempted to use <code>:line</code> events as David RodrÃguez suggested above, but on returns the value is always pointing to the deepest part of the stack most recently touched. The method does work well for calls though (albeit expensive to trace every line event).</p>
<p>You can see the different results (along with my personal expectation of what <em>should</em> be returned) in this gist: <a href="https://gist.github.com/jahfer/092e44df6f15298bae3cf47056301708#gistcomment-2015893" class="external">https://gist.github.com/jahfer/092e44df6f15298bae3cf47056301708#gistcomment-2015893</a></p> Ruby master - Bug #7976: TracePoint call is at call point, not call sitehttps://bugs.ruby-lang.org/issues/7976?journal_id=642862017-04-17T07:59:54Zshyouhei (Shyouhei Urabe)shyouhei@ruby-lang.org
<ul><li><strong>Status</strong> changed from <i>Feedback</i> to <i>Assigned</i></li></ul> Ruby master - Bug #7976: TracePoint call is at call point, not call sitehttps://bugs.ruby-lang.org/issues/7976?journal_id=693042018-01-05T21:00:40Znaruse (Yui NARUSE)naruse@airemix.jp
<ul><li><strong>Target version</strong> deleted (<del><i>2.2.0</i></del>)</li></ul> Ruby master - Bug #7976: TracePoint call is at call point, not call sitehttps://bugs.ruby-lang.org/issues/7976?journal_id=1030242023-05-10T01:00:46Zjeremyevans0 (Jeremy Evans)merch-redmine@jeremyevans.net
<ul><li><strong>Status</strong> changed from <i>Assigned</i> to <i>Closed</i></li></ul><p><a class="user active user-mention" href="https://bugs.ruby-lang.org/users/286">@headius (Charles Nutter)</a> and I agree this is not a bug. JRuby has similar behavior for Java extensions as CRuby does for C extensions.</p>