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.
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
detailed explanation of exclusive vs inclusive function time.
The following traces the firefox startup script.
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
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.