Project

General

Profile

Actions

Bug #7976

closed

TracePoint call is at call point, not call site

Added by zenspider (Ryan Davis) about 11 years ago. Updated 10 months ago.

Status:
Closed
Target version:
-
ruby -v:
2.0
Backport:
[ruby-core:52971]

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 :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.


Files

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

Updated by tenderlovemaking (Aaron Patterson) about 11 years ago

  • Category changed from YARV to core

Updated by deivid (David Rodríguez) over 10 years 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?

Updated by ko1 (Koichi Sasada) over 10 years ago

  • Target version set to 2.1.0

Updated by ko1 (Koichi Sasada) over 10 years 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, :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?

Updated by hsbt (Hiroshi SHIBATA) about 10 years ago

  • Target version changed from 2.1.0 to 2.2.0

Updated by jahfer (Jahfer Husain) about 7 years ago

I recently found this behaviour while attempting to build a gem that outputs the full call graph for our Rails application.

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 caller_locations, which computes the full backtrace from the VM and is a significant slowdown when compared to using rb_tracearg_path.

As a point of comparison, we can run 63k tests (parallelized) while invoking rb_tracearg_path in roughly 10 minutes, whereas using caller_locations takes about 1.5 hours to complete.

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.

I also attempted to use :line 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).

You can see the different results (along with my personal expectation of what should be returned) in this gist: https://gist.github.com/jahfer/092e44df6f15298bae3cf47056301708#gistcomment-2015893

Actions #7

Updated by shyouhei (Shyouhei Urabe) almost 7 years ago

  • Status changed from Feedback to Assigned
Actions #8

Updated by naruse (Yui NARUSE) about 6 years ago

  • Target version deleted (2.2.0)

Updated by jeremyevans0 (Jeremy Evans) 10 months ago

  • Status changed from Assigned to Closed

@headius (Charles Nutter) and I agree this is not a bug. JRuby has similar behavior for Java extensions as CRuby does for C extensions.

Actions

Also available in: Atom PDF

Like0
Like0Like0Like0Like0Like0Like0Like0Like0Like0