diff options
Diffstat (limited to 'Examples/rb_calldist_example.txt')
| -rw-r--r-- | Examples/rb_calldist_example.txt | 153 |
1 files changed, 153 insertions, 0 deletions
diff --git a/Examples/rb_calldist_example.txt b/Examples/rb_calldist_example.txt new file mode 100644 index 000000000000..088497c56286 --- /dev/null +++ b/Examples/rb_calldist_example.txt @@ -0,0 +1,153 @@ +The following is an example of running rb_calldist.d and tracing the elapsed +times for functions. + +We run rb_calldist.d while running the program Code/Ruby/func_abc.rb. We can +see that there are three sections in the DTrace output + +# rb_calldist.d +Tracing... Hit Ctrl-C to end. +^C + +Elapsed 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 | 0 + 16 |@@@@@@@@@@@@@ 1 + 32 | 0 + + +Exclusive function elapsed times (us), + func_abc.rb, func, Module::method_added + value ------------- Distribution ------------- count + 1 | 0 + 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 + 4 |@@@@@@@@@@@@@ 1 + 8 | 0 + + func_abc.rb, func, Object::print + value ------------- Distribution ------------- count + 8 | 0 + 16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 + 32 |@@@@@@@@@@@@@ 1 + 64 | 0 + + func_abc.rb, func, IO::write + value ------------- Distribution ------------- count + 16 | 0 + 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 + 64 |@@@@@@@@@@@@@ 1 + 128 | 0 + + func_abc.rb, func, Object::func_a + value ------------- Distribution ------------- count + 128 | 0 + 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 + 512 | 0 + + func_abc.rb, func, Object::func_b + value ------------- Distribution ------------- count + 128 | 0 + 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 + 512 | 0 + + func_abc.rb, func, Object::func_c + value ------------- Distribution ------------- count + 128 | 0 + 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 + 512 | 0 + + func_abc.rb, func, Object::sleep + value ------------- Distribution ------------- count + 262144 | 0 + 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 + 1048576 | 0 + + +Inclusive function elapsed times (us), + func_abc.rb, func, Module::method_added + value ------------- Distribution ------------- count + 1 | 0 + 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 + 4 |@@@@@@@@@@@@@ 1 + 8 | 0 + + func_abc.rb, func, IO::write + value ------------- Distribution ------------- count + 16 | 0 + 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 + 64 |@@@@@@@@@@@@@ 1 + 128 | 0 + + func_abc.rb, func, Object::print + value ------------- Distribution ------------- count + 32 | 0 + 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 + 128 |@@@@@@@@@@@@@ 1 + 256 | 0 + + func_abc.rb, func, Object::func_c + value ------------- Distribution ------------- count + 262144 | 0 + 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 + 1048576 | 0 + + func_abc.rb, func, Object::func_b + value ------------- Distribution ------------- count + 524288 | 0 + 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 + 2097152 | 0 + + func_abc.rb, func, Object::sleep + value ------------- Distribution ------------- count + 262144 | 0 + 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 + 1048576 | 0 + + func_abc.rb, func, Object::func_a + value ------------- Distribution ------------- count + 1048576 | 0 + 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 + 4194304 | 0 + +The elapsed times show us that the script spent some small amount of time +processing various events that were not functions. In this case they were all +obj-new events, and you can see that the slowest of these was a new Object at +between 16 microseconds and 31 microseconds. + +The exclusive subroutine elapsed times show that each of our user defined +functions took between 256 and 511 microseconds. This time excludes the time +spent in other subroutines. + +The inclusive subroutine elapsed times show that func_c() took between 0.5 +seconds and 1 second, func_b() took between 1 second and 2.1 seconds, and +func_a() took between 2.1 seconds and 4.2 seconds to execute. This time +includes the time spent in other subroutines called, and since func_a() called +func_b() which called func_c(), these times make sense. + |