Paul Ingles

I’d read a while back that Apple were going to include Sun’s DTrace tool in the now newly released Leopard - underpinning Instruments (formerly known as Xray).

What I hadn’t noticed was that the build of Ruby 1.8.6 included in Leopard (patchlevel 36 with some extras) also includes Ruby probes from the lovely folks at Joyent. Apple have ported everything. So, out of the box, Ruby works with DTrace! Sweet!

From Sun’s page:

DTrace is a comprehensive dynamic tracing facility that is built into Solaris and can be used by administrators and developers to examine the behavior of both user programs and of the operating system itself. With DTrace you can explore your system to understand how it works, track down performance problems across many layers of software, or locate the cause of aberrant behavior.

Joyent have got some sample scripts in their Subversion repository, and, what looks like some nice extensions for Rails (DTrace probes can be fired from within Ruby). Blimey!

For those (running Leopard) and want to just see something, try this out. It’s a script that traces the number of times a method is called. Once downloaded, all you need to do is

$ chmod +x functime.d
$ sudo ./functime.d -p <pid>

Replacing <pid> with the process id for your target Ruby process. Once you stop tracing (or your target process ends you’ll see some nice text formatted output. Including something like the following (from my current project):

Hash                     key?                     25123         15       384174
Module                   each_object                  1     390824       390824
Module                   included_in_classes          1     391025       391025
Module                   reloadable_classes_with      1     391203       391203
Module                   reloadable_classes           1     391835       391835
ActionController::Routin load_routes!                 1     394864       394864
ActionController::Routin reload                       1     398364       398364
Class                    reset_application!           1     398947       398947
Class                    reset_after_dispatch         1     400474       400474
ActionController::Routin connect                     39      13192       514506
Array                    include?                  3353        166       556605
ActionController::Routin build                       47      13116       616459
ActionController::Routin add_route                   47      13329       626488
Array                    each                       874        780       682423
Object                   load                         2     376432       752864
Module                   silence                      2     391586       783172
Kernel                   gem_original_require        28      43460      1216884
Array                    select                     316       4106      1297580
Array                    collect                    351       4124      1447524
Module                   local_constants             91      17120      1557986
Module                   new_constants_in            25      93885      2347139
Object                   require                     50      58495      2924783

The columns (from left to right) are: Class, Method, Count (number of times method was called) and then the average and total micro seconds. The d script was one of the Joyent examples. Arstechnica also have a very cool example showing the call stack from a system call.

What’s more amazing is this doesn’t require any recompilation, special flags, running in special environments. It’s available from the off!

If all that’s whetted your appetite (and I’m not sure how it couldn’t), head on over to the DTrace how to for a little more explanation of how it all works.

Time to get stuck in and see whether anything emerges about my current project. Very cool stuff!