←SystemTap and ruby 2.0
As you might know already that the second preview of ruby 2.0 interpreter has been released recently. And there is dtrace support among other cool features. I’m not fan of Solaris like others and use just Debian GNU/Linux. But linux still has a tool which intended to solve similar tasks: SystemTap. And it is possible to use it with applications where dtrace support enabled as said on their wiki:
These calls are source compatible with dtrace on other platforms, so the same source code compiled on a system that doesn’t have systemtap available, but does have a dtrace implementation will be able to discover the same probe locations.
Let check if it is true for ruby.
Setup
To use probepoints in ruby interpreter you should have a kernel with UPROBES enabled:
~ $ grep UPROBES /boot/config-*
/boot/config-3.6-trunk-amd64:CONFIG_ARCH_SUPPORTS_UPROBES=y
/boot/config-3.6-trunk-amd64:CONFIG_UPROBES=y
At this moment debian doesn’t ship kernels with this option, but building custom kernel isn’t a complex task these days.
And of course SystemTap itself. I had an runtime compilation issue with version from Debian repository (version 1.7-1+b1). The problem reported as Bug 14220 and fixed in e14ac0e. If you have similar issues, just install recent stable version.
So given you have all prerequisites installed, just download and build the ruby. It will automatically detect and configure SystemTap probes. To verify installation, let just ask it to output all accessible probes:
~ $ stap -L 'process("/usr/local/bin/ruby").mark("*")'
process("/usr/local/bin/ruby").mark("array__create") $arg1:long $arg2:long $arg3:long
process("/usr/local/bin/ruby").mark("cmethod__entry") $arg1:long $arg2:long $arg3:long $arg4:long
process("/usr/local/bin/ruby").mark("cmethod__return") $arg1:long $arg2:long $arg3:long $arg4:long
process("/usr/local/bin/ruby").mark("find__require__entry") $arg1:long $arg2:long $arg3:long
process("/usr/local/bin/ruby").mark("find__require__return") $arg1:long $arg2:long $arg3:long
process("/usr/local/bin/ruby").mark("gc__mark__begin")
process("/usr/local/bin/ruby").mark("gc__mark__end")
process("/usr/local/bin/ruby").mark("gc__sweep__begin")
process("/usr/local/bin/ruby").mark("gc__sweep__end")
process("/usr/local/bin/ruby").mark("hash__create") $arg1:long $arg2:long $arg3:long
process("/usr/local/bin/ruby").mark("load__entry") $arg1:long $arg2:long $arg3:long
process("/usr/local/bin/ruby").mark("load__return") $arg1:long
process("/usr/local/bin/ruby").mark("method__entry") $arg1:long $arg2:long $arg3:long $arg4:long
process("/usr/local/bin/ruby").mark("method__return") $arg1:long $arg2:long $arg3:long $arg4:long
process("/usr/local/bin/ruby").mark("object__create") $arg1:long $arg2:long $arg3:long
process("/usr/local/bin/ruby").mark("parse__begin") $arg1:long $arg2:long
process("/usr/local/bin/ruby").mark("parse__end") $arg1:long $arg2:long
process("/usr/local/bin/ruby").mark("raise") $arg1:long $arg2:long $arg3:long
process("/usr/local/bin/ruby").mark("require__entry") $arg1:long $arg2:long $arg3:long
process("/usr/local/bin/ruby").mark("require__return") $arg1:long
process("/usr/local/bin/ruby").mark("string__create") $arg1:long $arg2:long $arg3:long
Okay, looks like it does define some useful probepoints. Original
probes.d could be found in ruby repository. Lets see if we can
extract something useful.
Counting ‘require’ in rails console
For example, determine how many files required when rails starts
console. To count all of then we will trace all points marked
require__entry. This is the simple script which does the job:
global nmodules = 0;
probe process("/usr/local/bin/ruby").mark("require__entry")
{
module = kernel_string($arg1)
file = kernel_string($arg2)
line = $arg3
printf("%s(%d) %s %s:%d required file `%s'\n", execname(), pid(), $$name, file, line, module)
nmodules++;
}
probe end {
printf("Total files: %d\n", nmodules);
delete nmodules;
}
As you can see the script just outputs the required file name and the
place where require command was called. And then outputs total number
of the calls. The partial output (full):
$ sudo stap rails-console-require.stp -c 'script/rails console'
ruby(420) require__entry ruby:0 required file `enc/encdb.so'
ruby(420) require__entry <internal:enc/prelude>:3 required file `enc/encdb.so'
ruby(420) require__entry <internal:enc/prelude>:3 required file `enc/trans/transdb.so'
ruby(420) require__entry <internal:gem_prelude>:1 required file `rubygems.rb'
... snip ...
Total files: 966
“top” for ruby functions
Another interesting example taken from SystemTap wiki and slightly modified. It displays list of recent function calls for all ruby processes in the system. It also refresh the list each seconds.
global fn_calls;
probe process("/usr/local/bin/ruby").mark("method__entry")
{
signature = sprintf("%s#%s", kernel_string($arg1), kernel_string($arg2))
source = sprintf("%s:%d", kernel_string($arg3), $arg4)
fn_calls[pid(), signature, source] <<< 1;
}
probe process("/usr/local/bin/ruby").mark("cmethod__entry")
{
signature = sprintf("%s.%s", kernel_string($arg1), kernel_string($arg2))
source = sprintf("%s:%d", kernel_string($arg3), $arg4)
fn_calls[pid(), signature, source] <<< 1;
}
probe timer.ms(1000) {
ansi_clear_screen()
printf("%-6s %-6s %-30s %-40s\n",
"PID", "CALLS", "FUNCTION", "FILENAME")
foreach ([pid, signature, source] in fn_calls- limit 20) {
printf("%-6d %-6d %-40s %-80s\n",
pid, @count(fn_calls[pid, signature, source]),
signature, source);
}
delete fn_calls;
}
The script collects stats and every seconds draw them in the table. In
this form it might be not very useful, but it is easy to modify the
script for your needs. Here is the sample output. I’m running with
option -DMAXMAPENTRIES=10000 to extend the size of fn_calls map.
$ sudo stap -DMAXMAPENTRIES=10000 rubytop.stp
PID CALLS FUNCTION FILENAME
3900 29598 IO.write /usr/local/lib/ruby/2.0.0/irb/ext/save-history.rb:92
4468 14799 String.chomp /usr/local/lib/ruby/2.0.0/irb/ext/save-history.rb:79
4468 2223 Module.=== /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1725
4468 2106 BasicObject.== /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1725
4468 2106 Kernel.=== /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1725
4468 837 File.file? /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1371
4468 780 Gem::Specification#default_value /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1437
4468 780 Symbol.to_s /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1729
4468 780 Kernel.instance_variable_set /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1729
4468 702 Kernel.initialize_dup /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1726
4468 702 Kernel.dup /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1726
4468 468 Array.initialize_copy /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1726
4468 390 Kernel.instance_variable_set /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1719
4468 390 Symbol.to_s /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1719
4468 309 Gem#suffixes /usr/local/lib/ruby/2.0.0/rubygems.rb:837
4468 289 Hash.[]= /usr/local/lib/ruby/2.0.0/rubygems.rb:962
4468 282 RbConfig#expand /usr/local/lib/ruby/2.0.0/x86_64-linux/rbconfig.rb:221
4468 282 String.gsub /usr/local/lib/ruby/2.0.0/x86_64-linux/rbconfig.rb:222
4468 279 Enumerable.any? /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1371
4468 279 Array.each /usr/local/lib/ruby/2.0.0/rubygems/specification.rb:1371
Conclusion
This post shows only the tip of the iceberg. I really recommend you to take a look at SystemTap, because it is very powerful tool which might tell you a lot about your system and application you are running. Also note that using dtrace/SystemTap doesn’t introduce a lot of overhead in the binary, therefore you can inspect your production deployments too.
More links: