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