1The following are examples of rb_cpudist.d. 2 3This script traces the on-CPU time of Ruby functions and prints a report in 4the form of a histogram. Here it traces the example program, 5Code/Ruby/func_slow.rb 6 7# rb_cpudist.d 8Tracing... Hit Ctrl-C to end. 9^C 10 11On-CPU 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 |@@@@@@@@@@@@@ 1 42 16 | 0 43 44 45Exclusive function on-CPU times (us), 46 func_slow.rb, func, Module::method_added 47 value ------------- Distribution ------------- count 48 0 | 0 49 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 50 2 | 0 51 52 func_slow.rb, func, Object::print 53 value ------------- Distribution ------------- count 54 2 | 0 55 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 56 8 |@@@@@@@@@@@@@ 1 57 16 | 0 58 59 func_slow.rb, func, IO::write 60 value ------------- Distribution ------------- count 61 16 | 0 62 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 63 64 |@@@@@@@@@@@@@ 1 64 128 | 0 65 66 func_slow.rb, func, Object::func_a 67 value ------------- Distribution ------------- count 68 131072 | 0 69 262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 70 524288 | 0 71 72 func_slow.rb, func, Object::func_b 73 value ------------- Distribution ------------- count 74 262144 | 0 75 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 76 1048576 | 0 77 78 func_slow.rb, func, Fixnum::< 79 value ------------- Distribution ------------- count 80 0 | 0 81 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 599556 82 2 | 72 83 4 | 35 84 8 | 128 85 16 | 158 86 32 | 49 87 64 | 3 88 128 | 2 89 256 | 0 90 91 func_slow.rb, func, Object::func_c 92 value ------------- Distribution ------------- count 93 524288 | 0 94 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 95 2097152 | 0 96 97 func_slow.rb, func, Fixnum::+ 98 value ------------- Distribution ------------- count 99 0 | 0 100 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1199062 101 2 | 138 102 4 | 74 103 8 | 279 104 16 | 344 105 32 | 91 106 64 | 9 107 128 | 0 108 256 | 3 109 512 | 0 110 111 112Inclusive function on-CPU times (us), 113 func_slow.rb, func, Module::method_added 114 value ------------- Distribution ------------- count 115 0 | 0 116 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 117 2 | 0 118 119 func_slow.rb, func, IO::write 120 value ------------- Distribution ------------- count 121 16 | 0 122 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 123 64 |@@@@@@@@@@@@@ 1 124 128 | 0 125 126 func_slow.rb, func, Object::print 127 value ------------- Distribution ------------- count 128 16 | 0 129 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 130 64 |@@@@@@@@@@@@@ 1 131 128 | 0 132 133 func_slow.rb, func, Fixnum::< 134 value ------------- Distribution ------------- count 135 0 | 0 136 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 599556 137 2 | 72 138 4 | 35 139 8 | 128 140 16 | 158 141 32 | 49 142 64 | 3 143 128 | 2 144 256 | 0 145 146 func_slow.rb, func, Fixnum::+ 147 value ------------- Distribution ------------- count 148 0 | 0 149 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1199062 150 2 | 138 151 4 | 74 152 8 | 279 153 16 | 344 154 32 | 91 155 64 | 9 156 128 | 0 157 256 | 3 158 512 | 0 159 160 func_slow.rb, func, Object::func_b 161 value ------------- Distribution ------------- count 162 1048576 | 0 163 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 164 4194304 | 0 165 166 func_slow.rb, func, Object::func_c 167 value ------------- Distribution ------------- count 168 1048576 | 0 169 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 170 4194304 | 0 171 172 func_slow.rb, func, Object::func_a 173 value ------------- Distribution ------------- count 174 2097152 | 0 175 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 176 8388608 | 0 177 178You can see that the results are in three sections. 179 180The first section shows us the on-CPU time for actions that were not of the 181type 'func'. 182 183The second section, Exclusive function on-CPU times, shows us the time spent 184on-CPU by various functions, not including time spent in subroutines. You can 185see here that Object::print had two instances of being on-CPU between 4 186microseconds and 7 microseconds, and once instance of being on-CPU between 8 187microseconds and 15 microseconds. 188 189The third section, Inclusive function on-CPU times, shows us the time spent 190on-CPU by various functions, including that time spent in subroutines called 191by those functions. You can see that here Object::print had two instances 192of being on-CPU between 32 microseconds and 63 microseconds, and one instance 193of being on-CPU between 64 microseconds and 127 microseconds. 194 195It is important to pay close attention to the third column, "count" as this 196will indicate if there were any instances in a particular timeframe, even if 197the number is too small to show up on the histogram clearly. See Inclusive 198function on-CPU time for Fixnum::+ for an example. 199 200