Bug #14582
openUnable to use `method__entry` and `method_return` tracing probes since 2.5
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,
Updated by guilhermereiscampos (Guilherme Reis Campos) over 6 years ago
- Description updated (diff)
Updated by guilhermereiscampos (Guilherme Reis Campos) over 6 years ago
- Description updated (diff)
Updated by guilhermereiscampos (Guilherme Reis Campos) over 6 years ago
- Description updated (diff)
Updated by guilhermereiscampos (Guilherme Reis Campos) over 6 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 6 years ago
guilhermekbsa@gmail.com 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) about 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: https://github.com/ruby/ruby/pull/4587
Updated by mame (Yusuke Endoh) about 2 years ago
- Related to Feature #14104: Remove `trace` instructions added
Updated by vo.x (Vit Ondruch) 9 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 */
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.
//
Updated by vo.x (Vit Ondruch) about 1 month ago
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.