From: "ko1 (Koichi Sasada)" <redmine@...>
Date: 2013-10-10T18:06:43+09:00
Subject: [ruby-core:57804] [ruby-trunk - Bug #7976][Feedback] TracePoint	call is at call point, not call site


Issue #7976 has been updated by ko1 (Koichi Sasada).

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, :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>'


And binding is also nearest Ruby level binding.

  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]

self of `times' method is `1'. 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?

----------------------------------------
Bug #7976: TracePoint call is at call point, not call site
https://bugs.ruby-lang.org/issues/7976#change-42410

Author: zenspider (Ryan Davis)
Status: Feedback
Priority: Normal
Assignee: ko1 (Koichi Sasada)
Category: core
Target version: current: 2.1.0
ruby -v: 2.0
Backport: 


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 :c_call or :b_call 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.


-- 
http://bugs.ruby-lang.org/