DTrace and Ruby
It’s been an exciting few weeks for DTrace. The party got started with Wez Furlong’s new PHP DTrace provider at OSCON. Then Devon O’Dell announced that he was starting to work in earnest on a DTrace port to FreeBSD. And now, Rich Lowe has made available a prototype Ruby DTrace provider. To install this, grab Ruby 1.8.2, apply Rich’s patch, and run ./configure with the --enable-dtrace option. When you run the resulting ruby, you’ll see two probes: function-entry and function-return. The arguments to these probes are as follows:
-
arg0is the name of the class (a pointer to a string within Ruby) -
arg1is the name of the method (also a pointer to a string within Ruby) -
arg2is the name of the file containing the call site (again, a pointer to a string within Ruby) -
arg3is the line number of the call site.
So if, for example, you’d like to know the classes and methods that are called in a particular Ruby script, you could do it with this simple D script:
#pragma D option quiet
ruby$target:::function-entry
{
@[copyinstr(arg0), copyinstr(arg1)] = count();
}
END
{
printf("%15s %30s %s\n", "CLASS", "METHOD", "COUNT");
printa("%15s %30s %@d\n", @);
}
To run this against the cal.rb that ships in the sample directory of Ruby, call the above script whatmethods.d and run it this way:
# dtrace -s ./whatmethods.d -c "../ruby ./cal.rb"
August 2005
S M Tu W Th F S
1 2 3 4 5 6
7 8 9 10 11 12 13
14 15 16 17 18 19 20
21 22 23 24 25 26 27
28 29 30 31
CLASS METHOD COUNT
Array <= 2
Hash each 2
Hash keys 2
Module attr 2
Module method_undefined 2
Module public 2
Rational coerce 2
Array + 3
Class civil_to_jd 3
Hash [] 3
Object collect 3
Array collect 4
Class inherited 4
Range each 4
String size 4
Module private_class_method 5
Object eval 5
Object require 5
String gsub 5
Class jd_to_wday 7
Class once 7
Date __8713__ 7
Date wday 7
Fixnum % 8
Array join 10
Hash []= 10
String + 10
Array each 11
NilClass to_s 11
Module alias_method 22
Module private 22
Symbol to_s 26
Module module_eval 28
Date mday 31
Object send 31
Date mon 42
Date __11105__ 43
Class jd_to_civil 45
Date succ 47
Class os? 48
Date + 49
Fixnum <= 49
String rjust 49
Class ajd_to_jd 50
Class clfloor 50
Date __10417__ 50
Integer to_i 50
Object Integer 50
Rational divmod 50
Rational to_i 50
Date 51
Date ajd 51
Date jd 51
Rational 51
Class new0 52
Date initialize 52
Integer to_r 52
Object singleton_method_added 67
Date civil 75
Symbol to_i 91
Float * 96
Float coerce 96
Fixnum / 97
Object frozen? 100
Rational - 104
Fixnum to_s 123
Array [] 141
Object class 150
Module method_added 154
Float / 186
Module === 200
Rational / 204
Rational + 248
Float floor 282
Fixnum << 306
Class reduce 356
Integer gcd 356
Object Rational 356
Fixnum + 414
Class new! 610
Rational initialize 610
Class new 612
Fixnum abs 712
Fixnum div 762
Fixnum * 1046
Fixnum 1970
Fixnum - 2398
Object kind_of? 2439
Fixnum >> 4698
Fixnum [] 7689
Fixnum == 11436
This may leave us with many questions. For example, there are a couple of calls to construct new objects – where are they coming from? To answer that question:
#pragma D option quiet
ruby$target:::function-entry
/copyinstr(arg1) == "initialize"/
{
@[copyinstr(arg0), copyinstr(arg2), arg3] = count();
}
END
{
printf("%-10s %-40s %-10s %s\n", "CLASS",
"INITIALIZED IN FILE", "AT LINE", "COUNT");
printa("%-10s %-40s %-10d %@d\n", @);
}
Calling the above whereinit.d, we can run it in a similar manner:
# dtrace -s ./whereinit.d -c "../ruby ./cal.rb"
August 2005
S M Tu W Th F S
1 2 3 4 5 6
7 8 9 10 11 12 13
14 15 16 17 18 19 20
21 22 23 24 25 26 27
28 29 30 31
CLASS INITIALIZED IN FILE AT LINE COUNT
Cal ./cal.rb 144 1
Date /usr/local/lib/ruby/1.8/date.rb 593 1
Date /usr/local/lib/ruby/1.8/date.rb 703 1
Date /usr/local/lib/ruby/1.8/date.rb 916 1
Time /usr/local/lib/ruby/1.8/date.rb 702 1
Date /usr/local/lib/ruby/1.8/date.rb 901 49
Rational /usr/local/lib/ruby/1.8/rational.rb 374 610
Looking at the Date class, it’s interesting to look at line 901 of file /usr/local/lib/ruby/1.8/date.rb:
897 # If +n+ is not a Numeric, a TypeError will be thrown. In
898 # particular, two Dates cannot be added to each other.
899 def + (n)
900 case n
901 when Numeric; return self.class.new0(@ajd + n, @of, @sg)
902 end
903 raise TypeError, 'expected numeric'
904 end
This makes sense: we’re initializing new Date instances in the + method for Date. And where are those coming from? It’s not hard to build a script that will tell us the file and line for the call site of an arbitrary class and method:
#pragma D option quiet
ruby$target:::function-entry
/copyinstr(arg0) == $$1 && copyinstr(arg1) == $$2/
{
@[copyinstr(arg2), arg3] = count();
}
END
{
printf("%-40s %-10s %s\n", "FILE", "LINE", "COUNT");
printa("%-40s %-10d %@d\n", @);
}
For this particular example (Date#+()), call the above wherecall.d and run it this way:
# dtrace -s ./wherecall.d "Date" "+" -c "../ruby ./cal.rb"
August 2005
S M Tu W Th F S
1 2 3 4 5 6
7 8 9 10 11 12 13
14 15 16 17 18 19 20
21 22 23 24 25 26 27
28 29 30 31
FILE LINE COUNT
./cal.rb 102 2
./cal.rb 60 6
./cal.rb 63 41
And looking at the indicated lines in cal.rb:
55 def pict(y, m)
56 d = (1..31).detect{|d| Date.valid_date?(y, m, d, @start)}
57 fi = Date.new(y, m, d, @start)
58 fi -= (fi.jd - @k + 1) % 7
59
60 ve = (fi..fi + 6).collect{|cu|
61 %w(S M Tu W Th F S)[cu.wday]
62 }
63 ve += (fi..fi + 41).collect{|cu|
64 if cu.mon == m then cu.send(@da) end.to_s
65 }
66
So this is doing exactly what we would expect, given the code. Now, if we were interested in making this perform a little better, we might be interested to know the work that is being induced by Date#+(). Here’s a script that reports the classes and methods called by a given class/method – and its callees:
#pragma D option quiet
ruby$target:::function-entry
/copyinstr(arg0) == $$1 && copyinstr(arg1) == $$2/
{
self->date = 1;
}
ruby$target:::function-entry
/self->date/
{
@[strjoin(strjoin(copyinstr(arg0), "#"),
copyinstr(arg1))] = count();
}
ruby$target:::function-return
/copyinstr(arg0) == $$1 && copyinstr(arg1) == $$2/
{
self->date = 0;
ndates++;
}
END
{
normalize(@, ndates);
printf("Each call to %s#%s() induced:\n\n", $$1, $$2);
printa("%@8d call(s) to %s()\n", @);
}
Calling the above whatcalls.d, we can answer the question about Date#+() this way:
# dtrace -s ./whatcalls.d "Date" "+" -c "../ruby ./cal.rb"
August 2005
S M Tu W Th F S
1 2 3 4 5 6
7 8 9 10 11 12 13
14 15 16 17 18 19 20
21 22 23 24 25 26 27
28 29 30 31
Each call to Date#+() induced:
1 call(s) to Class#new0()
1 call(s) to Class#reduce()
1 call(s) to Date#+()
1 call(s) to Date#initialize()
1 call(s) to Fixnum#+()
1 call(s) to Fixnum#<<()
1 call(s) to Integer#gcd()
1 call(s) to Module#===()
1 call(s) to Object#Rational()
1 call(s) to Object#class()
2 call(s) to Class#new()
2 call(s) to Class#new!()
2 call(s) to Fixnum#abs()
2 call(s) to Fixnum#div()
2 call(s) to Rational#+()
2 call(s) to Rational#initialize()
3 call(s) to Fixnum#*()
3 call(s) to Fixnum#()
23 call(s) to Fixnum#>>()
37 call(s) to Fixnum#[]()
52 call(s) to Fixnum#==()
That’s a lot of work for something that should be pretty simple! Indeed, it’s counterintuitive that, say, Integer#gcd() would be called from Date#+() – and it certainly seems suboptimal. I’ll leave further exploration into this as an exercise to the reader, but suffice it to say that this has to do with the use of a rational number in the Date class – the elimination of which would elminate most of the above calls and presumably greatly improve the performance of Date#+().
Now, Ruby aficionados may note that some of the above functionality has been available in Ruby by setting the set_trace_func function (upon which the Ruby profiler is implemented). While that’s true (to a point – the set_trace_func seems to be a pretty limited mechanism), the Ruby DTrace provider is nonetheless a great lurch forward for Ruby developers: it allows developers to use DTrace-specific constructs like aggregations and thread-local variables to hone in on a problem; it allows Ruby-related work performed lower in the stack (e.g., in the I/O subsystem, CPU dispatcher or network stack) to be connected to the Ruby code inducing it; it allows a running Ruby script to be instrumented (and reinstrumented) without stopping or restarting it; and it allows multiple, disjoint Ruby scripts to be coherently observed and understood as a single entity. More succinctly, it’s just damned cool. So thanks to Rich for developing the prototype provider – and if you’re a Ruby developer, enjoy!