154 lines
7.6 KiB
Plaintext
154 lines
7.6 KiB
Plaintext
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.
|
|
|