1The following are examples of sh_calltime.d. 2 3This script traces the elapsed time of Bourne shell functions and 4prints a report. Here it traces the example program, Code/Shell/func_abc.sh. 5 6 # sh_calltime.d 7 Tracing... Hit Ctrl-C to end. 8 ^C 9 10 Counts, 11 FILE TYPE NAME COUNT 12 func_abc.sh func func_a 1 13 func_abc.sh func func_b 1 14 func_abc.sh func func_c 1 15 func_abc.sh builtin echo 3 16 func_abc.sh cmd sleep 3 17 - total - 9 18 19 Elapsed times (us), 20 FILE TYPE NAME TOTAL 21 func_abc.sh builtin echo 108 22 func_abc.sh cmd sleep 3023760 23 - total - 3023868 24 25 Exclusive function elapsed times (us), 26 FILE TYPE NAME TOTAL 27 func_abc.sh func func_b 2629 28 func_abc.sh func func_c 2822 29 func_abc.sh func func_a 3249 30 - total - 8702 31 32 Inclusive function elapsed times (us), 33 FILE TYPE NAME TOTAL 34 func_abc.sh func func_c 1009659 35 func_abc.sh func func_b 2020077 36 func_abc.sh func func_a 3032571 37 38In total, three functions were called, one builtin and one command. 39 40The elapsed times show that 3.0 seconds was spent in the sleep command, 41which is what would be expected based on the script. 42 43The exclusive function elapsed times show that each function spent around 442.7 milliseconds of time processing code - while not in other functions. 45 46The inclusive function elapsed times show that func_a() took around 3.0 47seconds to execute, followed by func_b() at 2.0 seconds, and func_c() at 1.0. 48The inclusive time includes the time spent in other calls, and since 49func_a() called func_b() which called func_c(), and they all call "sleep 1", 50these times make sense. 51 52These elapsed times are the absolute time from when the function began to 53when it completed - which includes off-CPU time due to other system events 54such as I/O, scheduling, interrupts, etc. In particular, for this case it has 55included the time waiting for the sleep commands. 56 57Elapsed times are useful for identifying where latencies are. 58See Notes/ALLelapsed_notes.txt for more details. Also see 59Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 60detailed explanation of exclusive vs inclusive function time. 61 62If you study the func_abc.sh program alongside the above output, the numbers 63should make sense. 64 65 66 67The following traces the firefox start script. 68 69# sh_calltime.d 70Tracing... Hit Ctrl-C to end. 71^C 72 73Counts, 74 FILE TYPE NAME COUNT 75 firefox builtin break 1 76 firefox builtin pwd 1 77 firefox builtin test 1 78 firefox cmd /usr/lib/firefox/run-mozilla.sh 1 79 run-mozilla.sh builtin break 1 80 run-mozilla.sh builtin return 1 81 run-mozilla.sh builtin shift 1 82 run-mozilla.sh builtin type 1 83 run-mozilla.sh cmd /usr/lib/firefox/firefox-bin 1 84 run-mozilla.sh func moz_run_program 1 85 run-mozilla.sh func moz_test_binary 1 86 firefox builtin echo 2 87 firefox func moz_pis_startstop_scripts 2 88 firefox builtin cd 3 89 firefox builtin export 3 90 run-mozilla.sh builtin export 3 91 firefox builtin : 6 92 firefox func moz_spc_verbose_echo 6 93 firefox builtin [ 18 94 run-mozilla.sh builtin [ 20 95 - total - 103 96 97Elapsed times (us), 98 FILE TYPE NAME TOTAL 99 run-mozilla.sh builtin return 1 100 run-mozilla.sh builtin shift 1 101 run-mozilla.sh builtin break 2 102 firefox builtin break 4 103 run-mozilla.sh builtin export 6 104 firefox builtin export 10 105 firefox builtin : 15 106 firefox builtin pwd 50 107 firefox builtin cd 72 108 run-mozilla.sh builtin [ 210 109 firefox builtin echo 323 110 firefox builtin [ 480 111 run-mozilla.sh builtin type 486 112 firefox builtin test 15330 113 run-mozilla.sh cmd /usr/lib/firefox/firefox-bin 8941269 114 firefox cmd /usr/lib/firefox/run-mozilla.sh 9384335 115 - total - 18342766 116 117Exclusive function elapsed times (us), 118 FILE TYPE NAME TOTAL 119 run-mozilla.sh func moz_test_binary 54 120 firefox func moz_spc_verbose_echo 136 121 firefox func moz_pis_startstop_scripts 230221 122 run-mozilla.sh func moz_run_program 402343 123 - total - 632756 124 125Inclusive function elapsed times (us), 126 FILE TYPE NAME TOTAL 127 run-mozilla.sh func moz_test_binary 91 128 firefox func moz_spc_verbose_echo 151 129 firefox func moz_pis_startstop_scripts 230587 130 run-mozilla.sh func moz_run_program 9343826 131 132 133 134The output showed that the most inclusive function elapsed time was in 135moz_run_program() at 9.3 seconds, which comes as little suprise since 136I let firefox run for several seconds before closing it. That same duration 137explains the large command times in the elapsed times report. 138 139Of more interest are the exclusive function elapsed times, where 140moz_pis_startstop_scripts() was the slowest at 230 ms. Other areas of the 141report are also useful to sanity check your software - should it be calling 142these things? Especially if there are any commands called that can be 143builtins instead. 144 145