There is one small'n'hidden feature of RHEL 6.2 that popped up recently as an enhancement errata (RHSA-2011-1581). With this update, SystemTap probes have been added to the Ruby package. I was waiting for this feature, because at the time I was reading Aaron Patterson's excelent articleabout Ruby probing, this was not possible in Fedora or Red Hat Enterprise Linux by default. I mean without compilation and installation of DTrace or SystemTap.

Imagine you have a Ruby application that has some performance issues on a production server and it's running RHEL 6.2 or newer. Now it is possible to perform very detailed probing using SystemTap, which is similar technology to DTrace supported and developed by Red Hat.

It is possible to create probing scripts that are compiled as kernel modules and start them even on production servers without any change of running applications. It is possible to "look" into running applications and search for bottlenecks. Both DTrace and SystemTap are fantastic technologies.

Installation of SystemTap is easy and straightforward and for our purposes we do not need to install kernel devel and debug info packages.

# yum -y install systemtap systemtap-runtime ruby

If you plan to trace kernel and other low level stuff, pay a visit the SystemTap Beginners Guide, but this is quite enough for us.

Before we start, we will create a small Ruby example. In real situations you will be probing complex applications like Ruby on Rails or Sinatra. Let's call it factorial.rb.

# cat factorial.rb
def factorial n
  f = 1; for i in 1..n; f *= i; end; f
end
puts factorial 42

The first example is the easiest, actually taken from the SystemTap wiki. It it able to print all Ruby method calls. Create a file called calls.stp with the following content:

# cat calls.stp 
probe ruby.function.entry
{
  printf("%s => %s.%s in %s:%d\n", thread_indent(1),
         classname, methodname, file, line);
}
probe ruby.function.return
{
  printf("%s <= %s.%s in %s:%d\n", thread_indent(-1),
         classname, methodname, file, line);
}

Let's have some fun now.

# sudo stap calls.stp -c "ruby factorial.rb"
1405006117752879898543142606244511569936384000000000
     0 ruby(16160): => Module.method_added in factorial.rb:1
    13 ruby(16160): <= Module.method_added in factorial.rb:1
     0 ruby(16160): => Object.factorial in factorial.rb:5
    25 ruby(16160):  => Range.each in factorial.rb:2
    61 ruby(16160):   => Fixnum.* in factorial.rb:2
    ... about twenty lines removed ...
   705 ruby(16160):   <= Bignum.* in factorial.rb:2
   712 ruby(16160):  <= Range.each in factorial.rb:2
   718 ruby(16160): <= Object.factorial in factorial.rb:2
     0 ruby(16160): => Object.puts in factorial.rb:5
    20 ruby(16160):  => Bignum.to_s in factorial.rb:5
    38 ruby(16160):  <= Bignum.to_s in factorial.rb:5
    53 ruby(16160):  => IO.write in factorial.rb:5
    74 ruby(16160):  <= IO.write in factorial.rb:5
    81 ruby(16160):  => IO.write in factorial.rb:5
    99 ruby(16160):  <= IO.write in factorial.rb:5
   106 ruby(16160): <= Object.puts in factorial.rb:5

Please note you have to run SystemTap under root account and also expect the first run to be a little bit slower, because SystemTap is compiling and inserting a kernel module under the hood.

By the way the big number (1405006117752879898543142606244511569936384000000000) is the actual output of our Ruby script. Yes, it's the world-famous 42! By the way it does not worth googling it - nothing special is found.

What about to count method calls now? I prepared a short script for that. If you are interested in the SystemTap syntax, google around or read whole Beginners Guide.

# cat rubycount.stp 
#!/usr/bin/stap 

global fn_calls;

probe ruby.function.entry
{ 
  fn_calls[classname, methodname] <<< 1;
}

probe end {
  foreach ([classname, methodname] in fn_calls- limit 30) {
    printf("%dx %s.%s\n",
        @count(fn_calls[classname, methodname]),
        classname, methodname);
  }

  delete fn_calls;
}

As you can see, it only counts all method calls and prints them when program ends. The output is much more useful.

# sudo stap rubycount.stp -c "ruby factorial.rb"
1405006117752879898543142606244511569936384000000000
21x Bignum.*
21x Fixnum.*
2x IO.write
1x Module.method_added
1x Range.each
1x Bignum.to_s
1x Object.puts
1x Object.factorial

We have a catch! The need to optimize multiply methods :-)

Let's be serious again. Do you want to see more? I offer nothing more than a recommendation for you. Write your own scripts. Probe anything you want. You take a deep look on Ruby classes, methods, files, lines, garbage collector, exceptions and user defined probe points. SystemTap is very flexible and easy to use.

I have one more script for you, which can be downloaded from the wiki. It's called rubyfuntop.stp and it is a comfortable way of watching guts of Ruby processes. Something like "top", but with more information like methods and files. It is also a good example of live SystemTap technique. To run it just give it an exec flag:

# chmod +x rubyfuntop.stp
# sudo ./rubyfuntop.stp

Then execute the factorial in a different console.

For your information SystemTap for Ruby did not hit Fedora yet, I hope it will be part of Ruby 1.8 as well as Ruby 1.9 that is planned for Fedora 17. Have fun!