Project

General

Profile

Actions

Bug #14582

open

Unable to use `method__entry` and `method_return` tracing probes since 2.5

Added by guilhermereiscampos (Guilherme Reis Campos) about 5 years ago. Updated almost 2 years ago.

Status:
Open
Priority:
Normal
Assignee:
-
Target version:
-
[ruby-core:85959]

Description

Hi,

I am trying to use dtrace/systemtap probes and not being able to use it after the 2.5. The 2.4 version works fine. I was hoping this was fixed on 2.6-preview, but apparently not (just downloaded dev and tested).

I tried on OSX using dtrace and also on ubuntu (vagrant).

# test.rb
class Foo

  def bar
    100.times { "Bar" }
  end
end

foo = Foo.new
foo.bar
# test.stp
probe process("/home/vagrant/.rbenv/versions/2.4.0/bin/ruby").mark("method__entry") # you will need to change this to your ruby path of your version.
{
	printf("%s => %s.%s in %s:%d\n", thread_indent(1), kernel_string($arg1),kernel_string($arg2),kernel_string($arg3),$arg4);
}
probe process("/home/vagrant/.rbenv/versions/2.4.0/bin/ruby").mark("method__return")
{
    printf("%s <= %s.%s in %s:%d\n", thread_indent(-1), kernel_string($arg1),kernel_string($arg2),kernel_string($arg3),$arg4);
} 

dtrace was something similar to it.

I was expecting to see this output:

# lots of calls
# ....
# then:
  4090 ruby(9667):   <= Gem::Specification.unresolved_deps in /home/vagrant/.rbenv/versions/2.4.0/lib/ruby/2.4.0/rubygems/specification.rb:1298
  4095 ruby(9667):   => MonitorMixin.mon_exit in /home/vagrant/.rbenv/versions/2.4.0/lib/ruby/2.4.0/monitor.rb:197
  4100 ruby(9667):    => MonitorMixin.mon_check_owner in /home/vagrant/.rbenv/versions/2.4.0/lib/ruby/2.4.0/monitor.rb:247
  4104 ruby(9667):    <= MonitorMixin.mon_check_owner in /home/vagrant/.rbenv/versions/2.4.0/lib/ruby/2.4.0/monitor.rb:251
  4109 ruby(9667):   <= MonitorMixin.mon_exit in /home/vagrant/.rbenv/versions/2.4.0/lib/ruby/2.4.0/monitor.rb:204
  4283 ruby(9667):  <= Kernel.require in /home/vagrant/.rbenv/versions/2.4.0/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55
  4303 ruby(9667): <= Kernel.require in /home/vagrant/.rbenv/versions/2.4.0/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55
     0 ruby(9667): => Foo.bar in test.rb:3
    16 ruby(9667): <= Foo.bar in test.rb:5

(The output above is 2.4)

my ruby (all versions that I tested) was install with rb-env:

RUBY_CONFIGURE_OPTS='--enable-dtrace --disable-install-doc' rbenv install 2.5.0

I am happy to provide details if required. I'd also be happy to fix it if I have guidance.

Thanks,


Related issues 1 (0 open1 closed)

Related to Ruby master - Feature #14104: Remove `trace` instructionsClosedko1 (Koichi Sasada)Actions
Actions #1

Updated by guilhermereiscampos (Guilherme Reis Campos) about 5 years ago

  • Description updated (diff)
Actions #2

Updated by guilhermereiscampos (Guilherme Reis Campos) about 5 years ago

  • Description updated (diff)
Actions #3

Updated by guilhermereiscampos (Guilherme Reis Campos) about 5 years ago

  • Description updated (diff)

Updated by guilhermereiscampos (Guilherme Reis Campos) about 5 years ago

Oh. I decided to dig a little bit deeper. Found this this: https://bugs.ruby-lang.org/issues/14104 apparently is required to do:

TracePoint.new{}.enable

I've added to my code and it works.

I was expecting that this dynamic tracing (dtrace, systemtap) would be enabled since it's compiled with --enable-dtrace and also when listing the probes all the probes are shown.

vagrant@vagrant-ubuntu-trusty-64:/vagrant/ruby/tracing/SystemTap$ sudo stap test.stp -L 'process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("*")'
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("array__create") $arg1:long $arg2:long $arg3:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("cmethod__entry") $arg1:long $arg2:long $arg3:long $arg4:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("cmethod__return") $arg1:long $arg2:long $arg3:long $arg4:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("find__require__entry") $arg1:long $arg2:long $arg3:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("find__require__return") $arg1:long $arg2:long $arg3:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("gc__mark__begin")
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("gc__mark__end")
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("gc__sweep__begin")
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("gc__sweep__end")
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("hash__create") $arg1:long $arg2:long $arg3:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("load__entry") $arg1:long $arg2:long $arg3:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("load__return") $arg1:long $arg2:long $arg3:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("method__cache__clear") $arg1:long $arg2:long $arg3:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("method__entry") $arg1:long $arg2:long $arg3:long $arg4:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("method__return") $arg1:long $arg2:long $arg3:long $arg4:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("object__create") $arg1:long $arg2:long $arg3:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("parse__begin") $arg1:long $arg2:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("parse__end") $arg1:long $arg2:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("raise") $arg1:long $arg2:long $arg3:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("require__entry") $arg1:long $arg2:long $arg3:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("require__return") $arg1:long $arg2:long $arg3:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("string__create") $arg1:long $arg2:long $arg3:long
process("/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby").mark("symbol__create") $arg1:long $arg2:long $arg3:long

Some of the probes cases even work without the TracePoint.new{}.enable (For instance, parse_begin, parse_end)

For this script the output is:

TracePoint.new{}.enable
class Foo

  def bar
    100.times { "Bar" }
  end
end

foo = Foo.new
foo.bar
# sudo stap test.stp -c '/home/vagrant/.rbenv/versions/ruby-dev/bin/ruby test.rb'
# output:
#     0 ruby(27101): <= Gem::Dependency.to_specs in /home/vagrant/.rbenv/versions/ruby-dev/lib/ruby/2.6.0/rubygems/dependency.rb:310
#     9 ruby(27101): <= Gem::Dependency.to_spec in /home/vagrant/.rbenv/versions/ruby-dev/lib/ruby/2.6.0/rubygems/dependency.rb:322
#   13 ruby(27101): <= Kernel.gem in /home/vagrant/.rbenv/versions/ruby-dev/lib/ruby/2.6.0/rubygems/core_ext/kernel_gem.rb:65
#  5813 ruby(27101): => Foo.bar in test.rb:5
# 5856 ruby(27101): <= Foo.bar in test.rb:6

Updated by normalperson (Eric Wong) about 5 years ago

wrote:

Oh. I decided to dig a little bit deeper. Found this this:
https://bugs.ruby-lang.org/issues/14104 apparently is required
to do:

TracePoint.new{}.enable

I've added to my code and it works.

I was expecting that this dynamic tracing (dtrace, systemtap)
would be enabled since it's compiled with``` --enable-dtrace

Hmm... I had to make this change to get tests to pass,
but I'm not sure how I feel about it:
https://80x24.org/spew/20180605033704.GA32537@ailurophile/raw

The rest of the series to fix dtrace tests on FreeBSD 11:
https://80x24.org/spew/20180605032921.32337-1-e@80x24.org/raw
https://80x24.org/spew/20180605032921.32337-2-e@80x24.org/raw
https://80x24.org/spew/20180605032921.32337-3-e@80x24.org/raw

Updated by jeremyevans0 (Jeremy Evans) almost 2 years ago

I'm assuming this is still the case, but I cannot verify it as I don't have an environment that supports DTrace. I've submitted a pull request to document how to enable the DTrace probes, but a committer with actual DTrace knowledge will need to check and confirm it is correct: https://github.com/ruby/ruby/pull/4587

Actions #7

Updated by mame (Yusuke Endoh) 12 months ago

Actions

Also available in: Atom PDF

Like0
Like0Like0Like0Like0Like0Like0Like0