Bug #7976

TracePoint call is at call point, not call site

Added by Ryan Davis about 1 year ago. Updated 3 months ago.

[ruby-core:52971]
Status:Feedback
Priority:Normal
Assignee:Koichi Sasada
Category:core
Target version:current: 2.2.0
ruby -v:2.0 Backport:

Description

Using TracePoint to make a new tracer utility I'm finding it very difficult to actually trace where the origin is for type :call. Instead, I get the destination. This is not the case for :ccall or :bcall as they trace at the origin, not destination.

Reproduction attached. Notice how it outputs ":call wtf.rb:08 :x" where line 8 is the definition of x, not the call of x, yet the subsequent backtrace lists line 21 which is the original origin for the call to x.

tp_test.rb Magnifier (1.21 KB) Ryan Davis, 02/27/2013 10:25 AM

History

#1 Updated by Aaron Patterson about 1 year ago

  • Category changed from YARV to core

#2 Updated by David Rodríguez 10 months ago

I find this behaviour satisfactory for my purposes.

If I need the origin of a :call event I use the previous :line event. Is this wrong?

#3 Updated by Koichi Sasada 7 months ago

  • Target version set to 2.1.0

#4 Updated by Koichi Sasada 6 months ago

  • Status changed from Open to Feedback

This behavior is same as backtrace.
Nearest file name and line number is used for C call,
because there are no file name and line for C methods.

modify trace as follows:

tp = TracePoint.new(:call, :return, :ccall, :creturn, :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-mswin32110]
"\"tp
test.rb:5:in <main>'\":c_return tp_test.rb:05 :enable"
"\"tp_test.rb:7:in
'\":ccall tptest.rb:07 :inherited"
"\"tptest.rb:7:in <main>'\":c_return tp_test.rb:07 :inherited"
"\"tp_test.rb:8:in
class:X'\":c
call tptest.rb:08 :methodadded"
"\"tptest.rb:8:in <class:X>'\":c_return tp_test.rb:08 :method_added"
"\"tp_test.rb:12:in
class:X'\":c
call tptest.rb:12 :methodadded"
"\"tptest.rb:12:in <class:X>'\":c_return tp_test.rb:12 :method_added"
"\"tp_test.rb:16:in
class:X'\":c
call tptest.rb:16 :methodadded"
"\"tptest.rb:16:in <class:X>'\":c_return tp_test.rb:16 :method_added"
"\"tp_test.rb:21:in
'\":c
call tptest.rb:21 :new"
"\"tp
test.rb:21:in new'\":c_call tp_test.rb:21 :initialize"
"\"tp_test.rb:21:in
new'\":creturn tptest.rb:21 :initialize"
"\"tptest.rb:21:in <main>'\":c_return tp_test.rb:21 :new"
"\"tp_test.rb:8:in
x'\":call tp
test.rb:08 :x"
"\"tptest.rb:12:in y'\":call tp_test.rb:12 :y"
"\"tp_test.rb:16:in
z'\":call tp
test.rb:16 :z"
"\"tptest.rb:17:in z'\":c_call tp_test.rb:17 :raise"
"\"tp_test.rb:17:in
raise'\":c
call tptest.rb:17 :new"
"\"tp
test.rb:17:in new'\":c_call tp_test.rb:17 :initialize"
"\"tp_test.rb:17:in
new'\":creturn tptest.rb:17 :initialize"
"\"tptest.rb:17:in raise'\":c_return tp_test.rb:17 :new"
"\"tp_test.rb:17:in
z'\":c
call tptest.rb:17 :backtrace"
"\"tp
test.rb:17:in z'\":c_return tp_test.rb:17 :backtrace"
"\"tp_test.rb:17:in
z'\":raise tptest.rb:17 :z"
"\"tp
test.rb:17:in z'\":c_return tp_test.rb:17 :raise"
"\"tp_test.rb:17:in
z'\":return tptest.rb:17 :z"
"\"tp
test.rb:13:in y'\":return tp_test.rb:13 :y"
"\"tp_test.rb:9:in
x'\":return tptest.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
'

And binding is also nearest Ruby level binding.

tp = TracePoint.trace(:call, :return, :ccall, :creturn, :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, main]
[#, #, main]
[#, #, main]
[#, #, main]
[#, 1, main]
[#, 1, main]
[#, 1, main]
[#, 1, main]

self of times' method is1'. However, binding.eval('self') returns main. This means that binding is also used Ruby level.
This is limitation of current TracePoint.

What should be happen on such case?

#5 Updated by Hiroshi SHIBATA 3 months ago

  • Target version changed from 2.1.0 to current: 2.2.0

Also available in: Atom PDF