The following is an example of running rb_calldist.d and tracing the elapsed times for functions. We run rb_calldist.d while running the program Code/Ruby/func_abc.rb. We can see that there are three sections in the DTrace output # rb_calldist.d Tracing... Hit Ctrl-C to end. ^C Elapsed times (us), ., obj-new, NoMemoryError value ------------- Distribution ------------- count 1 | 0 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 4 | 0 ., obj-new, SystemStackError value ------------- Distribution ------------- count 1 | 0 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 4 | 0 ., obj-new, ThreadGroup value ------------- Distribution ------------- count 4 | 0 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 16 | 0 ., obj-new, fatal value ------------- Distribution ------------- count 4 | 0 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 16 | 0 ., obj-new, Object value ------------- Distribution ------------- count 1 | 0 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 4 | 0 8 | 0 16 |@@@@@@@@@@@@@ 1 32 | 0 Exclusive function elapsed times (us), func_abc.rb, func, Module::method_added value ------------- Distribution ------------- count 1 | 0 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 4 |@@@@@@@@@@@@@ 1 8 | 0 func_abc.rb, func, Object::print value ------------- Distribution ------------- count 8 | 0 16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 32 |@@@@@@@@@@@@@ 1 64 | 0 func_abc.rb, func, IO::write value ------------- Distribution ------------- count 16 | 0 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 64 |@@@@@@@@@@@@@ 1 128 | 0 func_abc.rb, func, Object::func_a value ------------- Distribution ------------- count 128 | 0 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 512 | 0 func_abc.rb, func, Object::func_b value ------------- Distribution ------------- count 128 | 0 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 512 | 0 func_abc.rb, func, Object::func_c value ------------- Distribution ------------- count 128 | 0 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 512 | 0 func_abc.rb, func, Object::sleep value ------------- Distribution ------------- count 262144 | 0 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 1048576 | 0 Inclusive function elapsed times (us), func_abc.rb, func, Module::method_added value ------------- Distribution ------------- count 1 | 0 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 4 |@@@@@@@@@@@@@ 1 8 | 0 func_abc.rb, func, IO::write value ------------- Distribution ------------- count 16 | 0 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 64 |@@@@@@@@@@@@@ 1 128 | 0 func_abc.rb, func, Object::print value ------------- Distribution ------------- count 32 | 0 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 128 |@@@@@@@@@@@@@ 1 256 | 0 func_abc.rb, func, Object::func_c value ------------- Distribution ------------- count 262144 | 0 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 1048576 | 0 func_abc.rb, func, Object::func_b value ------------- Distribution ------------- count 524288 | 0 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 2097152 | 0 func_abc.rb, func, Object::sleep value ------------- Distribution ------------- count 262144 | 0 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 1048576 | 0 func_abc.rb, func, Object::func_a value ------------- Distribution ------------- count 1048576 | 0 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 4194304 | 0 The elapsed times show us that the script spent some small amount of time processing various events that were not functions. In this case they were all obj-new events, and you can see that the slowest of these was a new Object at between 16 microseconds and 31 microseconds. The exclusive subroutine elapsed times show that each of our user defined functions took between 256 and 511 microseconds. This time excludes the time spent in other subroutines. The inclusive subroutine elapsed times show that func_c() took between 0.5 seconds and 1 second, func_b() took between 1 second and 2.1 seconds, and func_a() took between 2.1 seconds and 4.2 seconds to execute. This time includes the time spent in other subroutines called, and since func_a() called func_b() which called func_c(), these times make sense.