rb_cpudist_example.txt revision 1.1.1.1
1 The following are examples of rb_cpudist.d. 2 3 This script traces the on-CPU time of Ruby functions and prints a report in 4 the form of a histogram. Here it traces the example program, 5 Code/Ruby/func_slow.rb 6 7 # rb_cpudist.d 8 Tracing... Hit Ctrl-C to end. 9 ^C 10 11 On-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 45 Exclusive 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 112 Inclusive 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 178 You can see that the results are in three sections. 179 180 The first section shows us the on-CPU time for actions that were not of the 181 type 'func'. 182 183 The second section, Exclusive function on-CPU times, shows us the time spent 184 on-CPU by various functions, not including time spent in subroutines. You can 185 see here that Object::print had two instances of being on-CPU between 4 186 microseconds and 7 microseconds, and once instance of being on-CPU between 8 187 microseconds and 15 microseconds. 188 189 The third section, Inclusive function on-CPU times, shows us the time spent 190 on-CPU by various functions, including that time spent in subroutines called 191 by those functions. You can see that here Object::print had two instances 192 of being on-CPU between 32 microseconds and 63 microseconds, and one instance 193 of being on-CPU between 64 microseconds and 127 microseconds. 194 195 It is important to pay close attention to the third column, "count" as this 196 will indicate if there were any instances in a particular timeframe, even if 197 the number is too small to show up on the histogram clearly. See Inclusive 198 function on-CPU time for Fixnum::+ for an example. 199 200
Indexes created Tue May 05 00:25:04 UTC 2026