Bug #14582


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

Added by guilhermereiscampos (Guilherme Reis Campos) about 6 years ago. Updated 5 months ago.

Target version:



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" }

foo =
# 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): => in test.rb:3
    16 ruby(9667): <= 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.


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 6 years ago

  • Description updated (diff)
Actions #2

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

  • Description updated (diff)
Actions #3

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

  • Description updated (diff)

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

Oh. I decided to dig a little bit deeper. Found this this: apparently is required to do:{}.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("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{}.enable (For instance, parse_begin, parse_end)

For this script the output is:{}.enable
class Foo

  def bar
    100.times { "Bar" }

foo =
# 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): => in test.rb:5
# 5856 ruby(27101): <= in test.rb:6

Updated by normalperson (Eric Wong) almost 6 years ago


Oh. I decided to dig a little bit deeper. Found this this: apparently is required
to do:{}.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:

The rest of the series to fix dtrace tests on FreeBSD 11:

Updated by jeremyevans0 (Jeremy Evans) almost 3 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:

Actions #7

Updated by mame (Yusuke Endoh) almost 2 years ago

Updated by vo.x (Vit Ondruch) 5 months ago

Yes, this si still the case. And it is documented. Nevertheless, I don't think this is acceptable. The original DTrace probes implementation imposed nearly zero cost for runtime. Later it was somehow bound to TracePoint and now due to TracePoint being slow, the DTrace probes are disabled?

Just reading the code, (I have not tested this snipped, but) would something like this help?

diff --git a/vm_insnhelper.c b/vm_insnhelper.c
index 9f9d0fcfd8..ee0a77e9fb 100644
--- a/vm_insnhelper.c
+++ b/vm_insnhelper.c
@@ -6489,7 +6489,6 @@ vm_trace_hook(rb_execution_context_t *ec, rb_control_frame_t *reg_cfp, const VAL
     if (event & global_hooks->events) {
         /* increment PC because source line is calculated with PC-1 */
-        vm_dtrace(event, ec);
         rb_exec_event_hook_orig(ec, global_hooks, event, self, 0, 0, 0 , val, 0);
@@ -6622,6 +6621,8 @@ vm_trace(rb_execution_context_t *ec, rb_control_frame_t *reg_cfp)
                 vm_trace_hook(ec, reg_cfp, pc, RUBY_EVENT_RETURN, RUBY_EVENT_RETURN, global_hooks, bmethod_local_hooks_ptr, TOPN(0));
+            vm_dtrace(pc_events & RUBY_EVENT_CALL, ec);
             // Pin the iseq since `local_hooks_ptr` points inside the iseq's slot on the GC heap.
             // We need the pointer to stay valid in case compaction happens in a trace hook.

Also available in: Atom PDF