Prashant's Perceptions

DTrace support for Ruby

DTrace probe support is now into OpenSolaris - as of build 87. Siva, an engineer in my little Ruby team checked it into the free software gate last Tuesday night.

Pretty cool!

DTrace is a great way to profile Ruby programs without introducing much overhead into the program you're tracing. This is a real boon considering that overhead is a big problem with Ruby profilers today.

Also, you don't need to make _any_ changes to your Ruby programs in order to narrow your profile to a set of functions.

DTrace rocks.

Below is an example of how to use DTrace to profile Ruby programs. The program traces through method invocations in different classes, and indents nested invocations accordingly.

Here's the program:

[root@dn10 dtrace]$cat rb_funcalls.d 
#!/usr/sbin/dtrace -Zqs
 /*
 * How do you invoke this script?
 * Use dtrace -xbufsize=40m -Zqs rb_funcall.d -c "ruby my_arg1 my_arg2"
 * Where "ruby" is DTrace enabled.
 */


 /*
 * Thread local variable to
 * store the indentation level
 * during/after a function call.
 */
 self int indent;

 dtrace:::BEGIN
 {
    printf("Starting to trace\n");
 }

 ruby*:::function-entry
 {  
    /*
    * To ensure that we capture function
    * entries and returnes made by a thread
    * in order.
    */
    self->thread = 1;
 }
 
 ruby*:::function-entry
 /self->thread/
 {
    self->indent += 2;
    printf("%*s", self->indent, " ");
    printf("=> %s->%s\n", copyinstr(arg0), copyinstr(arg1)); 
 }
 
 ruby*:::function-return
 /self->thread/
 {
   printf("%*s", self->indent, " ");
   printf("<= %s->%s\n", copyinstr(arg0), copyinstr(arg1));
   self->indent -= 2;
 }

 dtrace:::END
 {
   printf("Finished tracing\n"); 
 }
[root@dn10 dtrace]$

There are a couple of ways to invoke this - either start a process through the DTrace command line, or attach to an existing Ruby process. We'll do the latter since our program is rather simple.

[root@dn10 dtrace]$cat /tmp/hello.rb
message = String.new("Hello World")
puts message
[root@dn10 dtrace]$

On uttering the appropriate DTrace mantra, the following ensues:

[root@dn10 dtrace]$dtrace -xbufsize=40m -Zqs rb_funcalls.d  -c "ruby /tmp/hello.rb"
Starting to trace
Hello World
  => Class->new
    => String->initialize
    <= String->initialize
  <= Class->new
  => Object->puts
    => IO->write
    <= IO->write
    => IO->write
    <= IO->write
  <= Object->puts
Finished tracing

A few comments about the invocation and the scripts are in order here. You don't need a very high value of xbufsize for a small data set, it's just illustrative. You really need the -Z option because it ensures that DTrace doesn't bail out with complaints that it couldn't find the ruby*:::function-return(and other) probes. DTrace would otherwise do that when dealing with application level probes.
Moving to the script, note that it address the probes as "ruby*". This means that the selected probes in all Ruby processes running on your system will be activated and profiled, not just in the command you just invoked. If you don't like that, and instead want to trace a specific process, two changes are in order:
1. In the script, change "ruby*" to "ruby$1"
2. when calling the script - use "dtrace -xbufsize=40m -Zqs rb_funcalls.d my_pid" . Where "my_pid" is the pid of the Ruby process you're interested in profiling.
You can obtain more data from the probes, such as the source file being interpreted, and the line number. Use arg2 and arg3. An example of how to use them is:

#!/usr/sbin/dtrace -Zqs

 ruby*:::function-entry
 {
    printf("Class name: %s, Method name %s, Source file %s,  Line number %d\n", copyinstr(arg0), copyinstr(arg1), copyinstr(arg2), arg3);
 }

To invoke the above script, just utter "dtrace -xbufsize=40m -Zqs rb_fn_info.d", and assuming that you have a ruby process already running in your system - you'll begin to see data like the below.(else use the -c option to launch a command. Or use ruby$1 and a command line argument for the pid that you'd like to latch on to)

[snip!]
Class name: Proc, Method name call, Source file /usr/ruby/1.8/lib/ruby/1.8/irb/ruby-lex.rb,  Line number 207
Class name: IRB::Context, Method name prompting?, Source file /usr/ruby/1.8/lib/ruby/1.8/irb.rb,  Line number 115
Class name: IRB::Context, Method name verbose?, Source file /usr/ruby/1.8/lib/ruby/1.8/irb/context.rb,  Line number 156
Class name: NilClass, Method name nil?, Source file /usr/ruby/1.8/lib/ruby/1.8/irb/context.rb,  Line number 144
Class name: Object, Method name kind_of?, Source file /usr/ruby/1.8/lib/ruby/1.8/irb/context.rb,  Line number 145
Class name: IO, Method name tty?, Source file /usr/ruby/1.8/lib/ruby/1.8/irb/context.rb,  Line number 156
Class name: Object, Method name kind_of?, Source file /usr/ruby/1.8/lib/ruby/1.8/irb/context.rb,  Line number 156
Class name: Object, Method name kind_of?, Source file /usr/ruby/1.8/lib/ruby/1.8/irb/context.rb,  Line number 157
Class name: IRB::Irb, Method name prompt, Source file /usr/ruby/1.8/lib/ruby/1.8/irb.rb,  Line number 116
Class name: Object, Method name dup, Source file /usr/ruby/1.8/lib/ruby/1.8/irb.rb,  Line number 266
Class name: String, Method name initialize_copy, Source file /usr/ruby/1.8/lib/ruby/1.8/irb.rb,  Line number 266
Class name: String, Method name gsub!, Source file /usr/ruby/1.8/lib/ruby/1.8/irb.rb,  Line number 267
Class name: Object, Method name ===, Source file /usr/ruby/1.8/lib/ruby/1.8/irb.rb,  Line number 269
Class name: String, Method name ==, Source file /usr/ruby/1.8/lib/ruby/1.8/irb.rb,  Line number 269
Class name: Object, Method name ===, Source file /usr/ruby/1.8/lib/ruby/1.8/irb.rb,  Line number 269
Class name: String, Method name ==, Source file /usr/ruby/1.8/lib/ruby/1.8/irb.rb,  Line number 269
[snip!]

And that's all it takes to get dangerous. You can of course do a lot of fancy profiling with all these(and I'll save that for a different entry, since I've got to get to bed in time for an early morning phone call

Posted at 11:17PM Mar 26, 2008 by prashant in Ruby  |