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.