mirror of
https://github.com/Stichting-MINIX-Research-Foundation/netbsd.git
synced 2025-09-14 01:26:56 -04:00
78 lines
4.2 KiB
Plaintext
78 lines
4.2 KiB
Plaintext
The following is an example of running rb_calltime.d and tracing the elapsed
|
|
times for functions.
|
|
|
|
We run rb_calltime.d while running the program Code/Ruby/func_abc.rb. We can
|
|
see that there are four sections in the DTrace output
|
|
|
|
# rb_calltime.d
|
|
Tracing... Hit Ctrl-C to end.
|
|
^C
|
|
|
|
Count,
|
|
FILE TYPE NAME COUNT
|
|
. obj-new NoMemoryError 1
|
|
. obj-new SystemStackError 1
|
|
. obj-new ThreadGroup 1
|
|
. obj-new fatal 1
|
|
func_abc.rb func Object::func_a 1
|
|
func_abc.rb func Object::func_b 1
|
|
func_abc.rb func Object::func_c 1
|
|
. obj-new Object 3
|
|
func_abc.rb func IO::write 3
|
|
func_abc.rb func Module::method_added 3
|
|
func_abc.rb func Object::print 3
|
|
func_abc.rb func Object::sleep 3
|
|
- total - 15
|
|
|
|
Elapsed times (us),
|
|
FILE TYPE NAME TOTAL
|
|
. obj-new SystemStackError 3
|
|
. obj-new NoMemoryError 3
|
|
. obj-new fatal 11
|
|
. obj-new ThreadGroup 13
|
|
. obj-new Object 26
|
|
|
|
Exclusive function elapsed times (us),
|
|
FILE TYPE NAME TOTAL
|
|
func_abc.rb func Module::method_added 9
|
|
func_abc.rb func Object::print 92
|
|
func_abc.rb func IO::write 185
|
|
func_abc.rb func Object::func_c 344
|
|
func_abc.rb func Object::func_a 379
|
|
func_abc.rb func Object::func_b 383
|
|
func_abc.rb func Object::sleep 3020597
|
|
- total - 3021992
|
|
|
|
Inclusive function elapsed times (us),
|
|
FILE TYPE NAME TOTAL
|
|
func_abc.rb func Module::method_added 9
|
|
func_abc.rb func IO::write 185
|
|
func_abc.rb func Object::print 277
|
|
func_abc.rb func Object::func_c 1009829
|
|
func_abc.rb func Object::func_b 2019781
|
|
func_abc.rb func Object::sleep 3020597
|
|
func_abc.rb func Object::func_a 3021983
|
|
|
|
The first section, Count, shows us how many times each function associated
|
|
with func_abc.rb was called. It also shows other functions called by the Ruby
|
|
engine.
|
|
|
|
The second section, elapsed times, shows how long each action that was not
|
|
calling a function took.
|
|
|
|
The third section, exclusive function elapsed times, shows us how many
|
|
microseconds the program spends in each function. This does not include the
|
|
time spent in any sub-functions called by that particular function. The last
|
|
line gives us the total time in microseconds.
|
|
|
|
The fourth section, inclusive function elapsed times, are the absolute time
|
|
from when the function began to when it completed - which includes off-CPU time
|
|
due to other system events such as I/O, scheduling, interrupts, etc. In
|
|
particular, for this case it has included the time waiting for the sleep
|
|
commands.
|
|
|
|
Elapsed times are useful for identifying where latencies are.
|
|
See Notes/ALLelapsed_notes.txt for more details. Also see
|
|
Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
|
|
detailed explanation of exclusive vs inclusive function time.
|