Bug #14582: Unable to use `method__entry` and `method_return` tracing probes since 2.5

• Status: Open
• Assignee: -
• Target version: -
• ruby -v: 2.5
• Backport: 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: UNKNOWN
• Tags: tracepoint

[guilhermereiscampos (Guilherme Reis Campos)]

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,

[guilhermereiscampos (Guilherme Reis Campos)]

• Description updated (diff)

[guilhermereiscampos (Guilherme Reis Campos)]

• Description updated (diff)

[guilhermereiscampos (Guilherme Reis Campos)]

• Description updated (diff)

[guilhermereiscampos (Guilherme Reis Campos)]

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

[normalperson (Eric Wong)]

[e-mail] 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/[e-mail]/raw
https://80x24.org/spew/[e-mail]/raw
https://80x24.org/spew/[e-mail]/raw

[jeremyevans0 (Jeremy Evans)]

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

[mame (Yusuke Endoh)]

• Related to Feature #14104: Remove `trace` instructions added

[vo.x (Vit Ondruch)]

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 */
         reg_cfp->pc++;
-        vm_dtrace(event, ec);
         rb_exec_event_hook_orig(ec, global_hooks, event, self, 0, 0, 0 , val, 0);
         reg_cfp->pc--;
     }
@@ -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.
             //

[vo.x (Vit Ondruch)]

In Fedora / RHEL, we would still be interested in re-enabling this functionality. @jaruga (Jun Aruga) are there by a chance upstream SystemTap tests? I think that something similar to annocheck test coverage would be cool.

[jacobcarlborg (Jacob Carlborg)]

I'm really interested in using DTrace on Ruby as well. One of the major advantages of DTrace is that it's always available and doesn't require any code changes or restarts of the system that is being instrumented. But with the current way that USDT probes are implemented in Ruby it defeats many of the advantages of DTrace.