1 The following are examples of sh_calltime.d.
3 This script traces the elapsed time of Bourne shell functions and
4 prints a report. Here it traces the example program, Code/Shell/func_abc.sh.
7 Tracing... Hit Ctrl-C to end.
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
21 func_abc.sh builtin echo 108
22 func_abc.sh cmd sleep 3023760
25 Exclusive function elapsed times (us),
27 func_abc.sh func func_b 2629
28 func_abc.sh func func_c 2822
29 func_abc.sh func func_a 3249
32 Inclusive function elapsed times (us),
34 func_abc.sh func func_c 1009659
35 func_abc.sh func func_b 2020077
36 func_abc.sh func func_a 3032571
38 In total, three functions were called, one builtin and one command.
40 The elapsed times show that 3.0 seconds was spent in the sleep command,
41 which is what would be expected based on the script.
43 The exclusive function elapsed times show that each function spent around
44 2.7 milliseconds of time processing code - while not in other functions.
46 The inclusive function elapsed times show that func_a() took around 3.0
47 seconds to execute, followed by func_b() at 2.0 seconds, and func_c() at 1.0.
48 The inclusive time includes the time spent in other calls, and since
49 func_a() called func_b() which called func_c(), and they all call "sleep 1",
50 these times make sense.
52 These elapsed times are the absolute time from when the function began to
53 when it completed - which includes off-CPU time due to other system events
54 such as I/O, scheduling, interrupts, etc. In particular, for this case it has
55 included the time waiting for the sleep commands.
57 Elapsed times are useful for identifying where latencies are.
58 See Notes/ALLelapsed_notes.txt for more details. Also see
59 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
60 detailed explanation of exclusive vs inclusive function time.
62 If you study the func_abc.sh program alongside the above output, the numbers
67 The following traces the firefox start script.
70 Tracing... Hit Ctrl-C to end.
75 firefox builtin break 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
89 firefox builtin export 3
90 run-mozilla.sh builtin export 3
92 firefox func moz_spc_verbose_echo 6
94 run-mozilla.sh builtin [ 20
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
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
117 Exclusive function elapsed times (us),
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
125 Inclusive function elapsed times (us),
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
134 The output showed that the most inclusive function elapsed time was in
135 moz_run_program() at 9.3 seconds, which comes as little suprise since
136 I let firefox run for several seconds before closing it. That same duration
137 explains the large command times in the elapsed times report.
139 Of more interest are the exclusive function elapsed times, where
140 moz_pis_startstop_scripts() was the slowest at 230 ms. Other areas of the
141 report are also useful to sanity check your software - should it be calling
142 these things? Especially if there are any commands called that can be