1The following is an example of running rb_calldist.d and tracing the elapsed 2times for functions. 3 4We run rb_calldist.d while running the program Code/Ruby/func_abc.rb. We can 5see that there are three sections in the DTrace output 6 7# rb_calldist.d 8Tracing... Hit Ctrl-C to end. 9^C 10 11Elapsed times (us), 12 ., obj-new, NoMemoryError 13 value ------------- Distribution ------------- count 14 1 | 0 15 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 16 4 | 0 17 18 ., obj-new, SystemStackError 19 value ------------- Distribution ------------- count 20 1 | 0 21 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 22 4 | 0 23 24 ., obj-new, ThreadGroup 25 value ------------- Distribution ------------- count 26 4 | 0 27 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 28 16 | 0 29 30 ., obj-new, fatal 31 value ------------- Distribution ------------- count 32 4 | 0 33 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 34 16 | 0 35 36 ., obj-new, Object 37 value ------------- Distribution ------------- count 38 1 | 0 39 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 40 4 | 0 41 8 | 0 42 16 |@@@@@@@@@@@@@ 1 43 32 | 0 44 45 46Exclusive function elapsed times (us), 47 func_abc.rb, func, Module::method_added 48 value ------------- Distribution ------------- count 49 1 | 0 50 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 51 4 |@@@@@@@@@@@@@ 1 52 8 | 0 53 54 func_abc.rb, func, Object::print 55 value ------------- Distribution ------------- count 56 8 | 0 57 16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 58 32 |@@@@@@@@@@@@@ 1 59 64 | 0 60 61 func_abc.rb, func, IO::write 62 value ------------- Distribution ------------- count 63 16 | 0 64 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 65 64 |@@@@@@@@@@@@@ 1 66 128 | 0 67 68 func_abc.rb, func, Object::func_a 69 value ------------- Distribution ------------- count 70 128 | 0 71 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 72 512 | 0 73 74 func_abc.rb, func, Object::func_b 75 value ------------- Distribution ------------- count 76 128 | 0 77 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 78 512 | 0 79 80 func_abc.rb, func, Object::func_c 81 value ------------- Distribution ------------- count 82 128 | 0 83 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 84 512 | 0 85 86 func_abc.rb, func, Object::sleep 87 value ------------- Distribution ------------- count 88 262144 | 0 89 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 90 1048576 | 0 91 92 93Inclusive function elapsed times (us), 94 func_abc.rb, func, Module::method_added 95 value ------------- Distribution ------------- count 96 1 | 0 97 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 98 4 |@@@@@@@@@@@@@ 1 99 8 | 0 100 101 func_abc.rb, func, IO::write 102 value ------------- Distribution ------------- count 103 16 | 0 104 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 105 64 |@@@@@@@@@@@@@ 1 106 128 | 0 107 108 func_abc.rb, func, Object::print 109 value ------------- Distribution ------------- count 110 32 | 0 111 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 112 128 |@@@@@@@@@@@@@ 1 113 256 | 0 114 115 func_abc.rb, func, Object::func_c 116 value ------------- Distribution ------------- count 117 262144 | 0 118 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 119 1048576 | 0 120 121 func_abc.rb, func, Object::func_b 122 value ------------- Distribution ------------- count 123 524288 | 0 124 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 125 2097152 | 0 126 127 func_abc.rb, func, Object::sleep 128 value ------------- Distribution ------------- count 129 262144 | 0 130 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 131 1048576 | 0 132 133 func_abc.rb, func, Object::func_a 134 value ------------- Distribution ------------- count 135 1048576 | 0 136 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 137 4194304 | 0 138 139The elapsed times show us that the script spent some small amount of time 140processing various events that were not functions. In this case they were all 141obj-new events, and you can see that the slowest of these was a new Object at 142between 16 microseconds and 31 microseconds. 143 144The exclusive subroutine elapsed times show that each of our user defined 145functions took between 256 and 511 microseconds. This time excludes the time 146spent in other subroutines. 147 148The inclusive subroutine elapsed times show that func_c() took between 0.5 149seconds and 1 second, func_b() took between 1 second and 2.1 seconds, and 150func_a() took between 2.1 seconds and 4.2 seconds to execute. This time 151includes the time spent in other subroutines called, and since func_a() called 152func_b() which called func_c(), these times make sense. 153 154