The following are examples of rb_cpudist.d. This script traces the on-CPU time of Ruby functions and prints a report in the form of a histogram. Here it traces the example program, Code/Ruby/func_slow.rb # rb_cpudist.d Tracing... Hit Ctrl-C to end. ^C On-CPU 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 |@@@@@@@@@@@@@ 1 16 | 0 Exclusive function on-CPU times (us), func_slow.rb, func, Module::method_added value ------------- Distribution ------------- count 0 | 0 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 2 | 0 func_slow.rb, func, Object::print value ------------- Distribution ------------- count 2 | 0 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 8 |@@@@@@@@@@@@@ 1 16 | 0 func_slow.rb, func, IO::write value ------------- Distribution ------------- count 16 | 0 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 64 |@@@@@@@@@@@@@ 1 128 | 0 func_slow.rb, func, Object::func_a value ------------- Distribution ------------- count 131072 | 0 262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 524288 | 0 func_slow.rb, func, Object::func_b value ------------- Distribution ------------- count 262144 | 0 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 1048576 | 0 func_slow.rb, func, Fixnum::< value ------------- Distribution ------------- count 0 | 0 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 599556 2 | 72 4 | 35 8 | 128 16 | 158 32 | 49 64 | 3 128 | 2 256 | 0 func_slow.rb, func, Object::func_c value ------------- Distribution ------------- count 524288 | 0 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 2097152 | 0 func_slow.rb, func, Fixnum::+ value ------------- Distribution ------------- count 0 | 0 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1199062 2 | 138 4 | 74 8 | 279 16 | 344 32 | 91 64 | 9 128 | 0 256 | 3 512 | 0 Inclusive function on-CPU times (us), func_slow.rb, func, Module::method_added value ------------- Distribution ------------- count 0 | 0 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 2 | 0 func_slow.rb, func, IO::write value ------------- Distribution ------------- count 16 | 0 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 64 |@@@@@@@@@@@@@ 1 128 | 0 func_slow.rb, func, Object::print value ------------- Distribution ------------- count 16 | 0 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 64 |@@@@@@@@@@@@@ 1 128 | 0 func_slow.rb, func, Fixnum::< value ------------- Distribution ------------- count 0 | 0 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 599556 2 | 72 4 | 35 8 | 128 16 | 158 32 | 49 64 | 3 128 | 2 256 | 0 func_slow.rb, func, Fixnum::+ value ------------- Distribution ------------- count 0 | 0 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1199062 2 | 138 4 | 74 8 | 279 16 | 344 32 | 91 64 | 9 128 | 0 256 | 3 512 | 0 func_slow.rb, func, Object::func_b value ------------- Distribution ------------- count 1048576 | 0 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 4194304 | 0 func_slow.rb, func, Object::func_c value ------------- Distribution ------------- count 1048576 | 0 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 4194304 | 0 func_slow.rb, func, Object::func_a value ------------- Distribution ------------- count 2097152 | 0 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 8388608 | 0 You can see that the results are in three sections. The first section shows us the on-CPU time for actions that were not of the type 'func'. The second section, Exclusive function on-CPU times, shows us the time spent on-CPU by various functions, not including time spent in subroutines. You can see here that Object::print had two instances of being on-CPU between 4 microseconds and 7 microseconds, and once instance of being on-CPU between 8 microseconds and 15 microseconds. The third section, Inclusive function on-CPU times, shows us the time spent on-CPU by various functions, including that time spent in subroutines called by those functions. You can see that here Object::print had two instances of being on-CPU between 32 microseconds and 63 microseconds, and one instance of being on-CPU between 64 microseconds and 127 microseconds. It is important to pay close attention to the third column, "count" as this will indicate if there were any instances in a particular timeframe, even if the number is too small to show up on the histogram clearly. See Inclusive function on-CPU time for Fixnum::+ for an example.