1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 | 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.
|