diff options
Diffstat (limited to 'cddl/contrib/dtracetoolkit/Examples/rb_cpudist_example.txt')
| -rw-r--r-- | cddl/contrib/dtracetoolkit/Examples/rb_cpudist_example.txt | 199 |
1 files changed, 199 insertions, 0 deletions
diff --git a/cddl/contrib/dtracetoolkit/Examples/rb_cpudist_example.txt b/cddl/contrib/dtracetoolkit/Examples/rb_cpudist_example.txt new file mode 100644 index 000000000000..718495e394f0 --- /dev/null +++ b/cddl/contrib/dtracetoolkit/Examples/rb_cpudist_example.txt @@ -0,0 +1,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. + |