mirror of
https://github.com/Stichting-MINIX-Research-Foundation/netbsd.git
synced 2025-09-13 09:09:01 -04:00
310 lines
16 KiB
Plaintext
310 lines
16 KiB
Plaintext
The following are examples of sh_calldist.d.
|
|
|
|
This script traces the elapsed time of Bourne shell functions and
|
|
prints a report containing distribution plots per function. Here it
|
|
traces the example program, Code/Shell/func_abc.sh.
|
|
|
|
# sh_calldist.d
|
|
Tracing... Hit Ctrl-C to end.
|
|
^C
|
|
|
|
Elapsed times (us),
|
|
|
|
func_abc.sh, builtin, echo
|
|
value ------------- Distribution ------------- count
|
|
8 | 0
|
|
16 |@@@@@@@@@@@@@ 1
|
|
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
|
|
64 | 0
|
|
|
|
func_abc.sh, cmd, sleep
|
|
value ------------- Distribution ------------- count
|
|
262144 | 0
|
|
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
|
|
1048576 | 0
|
|
|
|
Exclusive function elapsed times (us),
|
|
|
|
func_abc.sh, func, func_a
|
|
value ------------- Distribution ------------- count
|
|
1024 | 0
|
|
2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
4096 | 0
|
|
|
|
func_abc.sh, func, func_b
|
|
value ------------- Distribution ------------- count
|
|
1024 | 0
|
|
2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
4096 | 0
|
|
|
|
func_abc.sh, func, func_c
|
|
value ------------- Distribution ------------- count
|
|
1024 | 0
|
|
2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
4096 | 0
|
|
|
|
Inclusive function elapsed times (us),
|
|
|
|
func_abc.sh, func, func_c
|
|
value ------------- Distribution ------------- count
|
|
262144 | 0
|
|
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
1048576 | 0
|
|
|
|
func_abc.sh, func, func_b
|
|
value ------------- Distribution ------------- count
|
|
524288 | 0
|
|
1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
2097152 | 0
|
|
|
|
func_abc.sh, func, func_a
|
|
value ------------- Distribution ------------- count
|
|
1048576 | 0
|
|
2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
4194304 | 0
|
|
|
|
The elapsed times show that the echo builtin takes between 16 and 64 us
|
|
to execute.
|
|
|
|
The exclusive function elapsed times show that each function spent
|
|
between 2 and 4 ms. This exclusive time excludes the time spent in
|
|
other functions.
|
|
|
|
The inclusive function elapsed times show that func_c() took between 0.5 and
|
|
1.0 seconds, func_b() took between 1.0 and 2.1 seconds, and func_a() took
|
|
between 2.1 and 4.2 seconds to execute. This inclusive time includes the
|
|
time spent in other functions and commands called, and since func_a()
|
|
calls func_b() which calls func_c(), and, each function is calling "sleep 1",
|
|
these times make sense.
|
|
|
|
These 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.
|
|
|
|
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.
|
|
|
|
|
|
|
|
The following traces the firefox startup script.
|
|
|
|
# sh_calldist.d
|
|
Tracing... Hit Ctrl-C to end.
|
|
^C
|
|
|
|
Elapsed times (us),
|
|
|
|
run-mozilla.sh, builtin, return
|
|
value ------------- Distribution ------------- count
|
|
0 | 0
|
|
1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
2 | 0
|
|
|
|
run-mozilla.sh, builtin, shift
|
|
value ------------- Distribution ------------- count
|
|
0 | 0
|
|
1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
2 | 0
|
|
|
|
run-mozilla.sh, builtin, break
|
|
value ------------- Distribution ------------- count
|
|
1 | 0
|
|
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
4 | 0
|
|
|
|
firefox, builtin, break
|
|
value ------------- Distribution ------------- count
|
|
2 | 0
|
|
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
8 | 0
|
|
|
|
run-mozilla.sh, builtin, export
|
|
value ------------- Distribution ------------- count
|
|
0 | 0
|
|
1 |@@@@@@@@@@@@@ 1
|
|
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
|
|
4 | 0
|
|
|
|
firefox, builtin, export
|
|
value ------------- Distribution ------------- count
|
|
1 | 0
|
|
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
|
|
4 |@@@@@@@@@@@@@ 1
|
|
8 | 0
|
|
|
|
firefox, builtin, :
|
|
value ------------- Distribution ------------- count
|
|
0 | 0
|
|
1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 5
|
|
2 | 0
|
|
4 |@@@@@@@ 1
|
|
8 | 0
|
|
|
|
firefox, builtin, pwd
|
|
value ------------- Distribution ------------- count
|
|
16 | 0
|
|
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
64 | 0
|
|
|
|
firefox, builtin, test
|
|
value ------------- Distribution ------------- count
|
|
16 | 0
|
|
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
64 | 0
|
|
|
|
firefox, builtin, cd
|
|
value ------------- Distribution ------------- count
|
|
4 | 0
|
|
8 |@@@@@@@@@@@@@ 1
|
|
16 |@@@@@@@@@@@@@ 1
|
|
32 |@@@@@@@@@@@@@ 1
|
|
64 | 0
|
|
|
|
firefox, builtin, [
|
|
value ------------- Distribution ------------- count
|
|
0 | 0
|
|
1 |@@@@@@@ 3
|
|
2 |@@ 1
|
|
4 |@@ 1
|
|
8 |@@@@@@@ 3
|
|
16 |@@@@@@@@@@@ 5
|
|
32 |@@@@@@@ 3
|
|
64 |@@@@ 2
|
|
128 | 0
|
|
|
|
run-mozilla.sh, builtin, type
|
|
value ------------- Distribution ------------- count
|
|
256 | 0
|
|
512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
1024 | 0
|
|
|
|
run-mozilla.sh, builtin, [
|
|
value ------------- Distribution ------------- count
|
|
0 | 0
|
|
1 |@@@@@@@@ 4
|
|
2 |@@@@@@@@@@ 5
|
|
4 |@@@@ 2
|
|
8 |@@@@@@ 3
|
|
16 |@@@@@@@@@@ 5
|
|
32 | 0
|
|
64 | 0
|
|
128 | 0
|
|
256 | 0
|
|
512 | 0
|
|
1024 | 0
|
|
2048 |@@ 1
|
|
4096 | 0
|
|
|
|
firefox, builtin, echo
|
|
value ------------- Distribution ------------- count
|
|
64 | 0
|
|
128 |@@@@@@@@@@@@@@@@@@@@ 1
|
|
256 | 0
|
|
512 | 0
|
|
1024 | 0
|
|
2048 |@@@@@@@@@@@@@@@@@@@@ 1
|
|
4096 | 0
|
|
|
|
firefox, cmd, /usr/lib/firefox/run-mozilla.sh
|
|
value ------------- Distribution ------------- count
|
|
2097152 | 0
|
|
4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
8388608 | 0
|
|
|
|
run-mozilla.sh, cmd, /usr/lib/firefox/firefox-bin
|
|
value ------------- Distribution ------------- count
|
|
2097152 | 0
|
|
4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
8388608 | 0
|
|
|
|
Exclusive function elapsed times (us),
|
|
|
|
run-mozilla.sh, func, moz_test_binary
|
|
value ------------- Distribution ------------- count
|
|
16 | 0
|
|
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
64 | 0
|
|
|
|
firefox, func, moz_spc_verbose_echo
|
|
value ------------- Distribution ------------- count
|
|
2 | 0
|
|
4 |@@@@@@@@@@@@@ 2
|
|
8 |@@@@@@@@@@@@@ 2
|
|
16 |@@@@@@@@@@@@@ 2
|
|
32 | 0
|
|
|
|
firefox, func, moz_pis_startstop_scripts
|
|
value ------------- Distribution ------------- count
|
|
128 | 0
|
|
256 |@@@@@@@@@@@@@@@@@@@@ 1
|
|
512 | 0
|
|
1024 | 0
|
|
2048 | 0
|
|
4096 | 0
|
|
8192 | 0
|
|
16384 | 0
|
|
32768 |@@@@@@@@@@@@@@@@@@@@ 1
|
|
65536 | 0
|
|
|
|
run-mozilla.sh, func, moz_run_program
|
|
value ------------- Distribution ------------- count
|
|
65536 | 0
|
|
131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
262144 | 0
|
|
|
|
Inclusive function elapsed times (us),
|
|
|
|
firefox, func, moz_spc_verbose_echo
|
|
value ------------- Distribution ------------- count
|
|
4 | 0
|
|
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
|
|
16 |@@@@@@@@@@@@@ 2
|
|
32 | 0
|
|
|
|
run-mozilla.sh, func, moz_test_binary
|
|
value ------------- Distribution ------------- count
|
|
32 | 0
|
|
64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
128 | 0
|
|
|
|
firefox, func, moz_pis_startstop_scripts
|
|
value ------------- Distribution ------------- count
|
|
128 | 0
|
|
256 |@@@@@@@@@@@@@@@@@@@@ 1
|
|
512 | 0
|
|
1024 | 0
|
|
2048 | 0
|
|
4096 | 0
|
|
8192 | 0
|
|
16384 | 0
|
|
32768 |@@@@@@@@@@@@@@@@@@@@ 1
|
|
65536 | 0
|
|
|
|
run-mozilla.sh, func, moz_run_program
|
|
value ------------- Distribution ------------- count
|
|
2097152 | 0
|
|
4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
|
|
8388608 | 0
|
|
|
|
|
|
As an example of interpreting the output: the inclusive elapsed time for
|
|
the "[" (test) builtin,
|
|
|
|
firefox, builtin, [
|
|
value ------------- Distribution ------------- count
|
|
0 | 0
|
|
1 |@@@@@@@ 3
|
|
2 |@@ 1
|
|
4 |@@ 1
|
|
8 |@@@@@@@ 3
|
|
16 |@@@@@@@@@@@ 5
|
|
32 |@@@@@@@ 3
|
|
64 |@@@@ 2
|
|
128 | 0
|
|
|
|
shows that it was called 17 times (after adding up the counts), 5 of which
|
|
took between 16 and 31 microseconds.
|
|
|