1 The following are examples of sh_calldist.d.
3 This script traces the elapsed time of Bourne shell functions and
4 prints a report containing distribution plots per function. Here it
5 traces the example program, Code/Shell/func_abc.sh.
8 Tracing... Hit Ctrl-C to end.
13 func_abc.sh, builtin, echo
14 value ------------- Distribution ------------- count
17 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
20 func_abc.sh, cmd, sleep
21 value ------------- Distribution ------------- count
23 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
26 Exclusive function elapsed times (us),
28 func_abc.sh, func, func_a
29 value ------------- Distribution ------------- count
31 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
34 func_abc.sh, func, func_b
35 value ------------- Distribution ------------- count
37 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
40 func_abc.sh, func, func_c
41 value ------------- Distribution ------------- count
43 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
46 Inclusive function elapsed times (us),
48 func_abc.sh, func, func_c
49 value ------------- Distribution ------------- count
51 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
54 func_abc.sh, func, func_b
55 value ------------- Distribution ------------- count
57 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
60 func_abc.sh, func, func_a
61 value ------------- Distribution ------------- count
63 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
66 The elapsed times show that the echo builtin takes between 16 and 64 us
69 The exclusive function elapsed times show that each function spent
70 between 2 and 4 ms. This exclusive time excludes the time spent in
73 The inclusive function elapsed times show that func_c() took between 0.5 and
74 1.0 seconds, func_b() took between 1.0 and 2.1 seconds, and func_a() took
75 between 2.1 and 4.2 seconds to execute. This inclusive time includes the
76 time spent in other functions and commands called, and since func_a()
77 calls func_b() which calls func_c(), and, each function is calling "sleep 1",
78 these times make sense.
80 These elapsed times are the absolute time from when the function began to
81 when it completed - which includes off-CPU time due to other system events
82 such as I/O, scheduling, interrupts, etc.
84 Elapsed times are useful for identifying where latencies are.
85 See Notes/ALLelapsed_notes.txt for more details. Also see
86 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
87 detailed explanation of exclusive vs inclusive function time.
91 The following traces the firefox startup script.
94 Tracing... Hit Ctrl-C to end.
99 run-mozilla.sh, builtin, return
100 value ------------- Distribution ------------- count
102 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
105 run-mozilla.sh, builtin, shift
106 value ------------- Distribution ------------- count
108 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
111 run-mozilla.sh, builtin, break
112 value ------------- Distribution ------------- count
114 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
117 firefox, builtin, break
118 value ------------- Distribution ------------- count
120 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
123 run-mozilla.sh, builtin, export
124 value ------------- Distribution ------------- count
127 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
130 firefox, builtin, export
131 value ------------- Distribution ------------- count
133 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
138 value ------------- Distribution ------------- count
140 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 5
145 firefox, builtin, pwd
146 value ------------- Distribution ------------- count
148 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
151 firefox, builtin, test
152 value ------------- Distribution ------------- count
154 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
158 value ------------- Distribution ------------- count
166 value ------------- Distribution ------------- count
177 run-mozilla.sh, builtin, type
178 value ------------- Distribution ------------- count
180 512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
183 run-mozilla.sh, builtin, [
184 value ------------- Distribution ------------- count
200 firefox, builtin, echo
201 value ------------- Distribution ------------- count
203 128 |@@@@@@@@@@@@@@@@@@@@ 1
207 2048 |@@@@@@@@@@@@@@@@@@@@ 1
210 firefox, cmd, /usr/lib/firefox/run-mozilla.sh
211 value ------------- Distribution ------------- count
213 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
216 run-mozilla.sh, cmd, /usr/lib/firefox/firefox-bin
217 value ------------- Distribution ------------- count
219 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
222 Exclusive function elapsed times (us),
224 run-mozilla.sh, func, moz_test_binary
225 value ------------- Distribution ------------- count
227 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
230 firefox, func, moz_spc_verbose_echo
231 value ------------- Distribution ------------- count
238 firefox, func, moz_pis_startstop_scripts
239 value ------------- Distribution ------------- count
241 256 |@@@@@@@@@@@@@@@@@@@@ 1
248 32768 |@@@@@@@@@@@@@@@@@@@@ 1
251 run-mozilla.sh, func, moz_run_program
252 value ------------- Distribution ------------- count
254 131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
257 Inclusive function elapsed times (us),
259 firefox, func, moz_spc_verbose_echo
260 value ------------- Distribution ------------- count
262 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
266 run-mozilla.sh, func, moz_test_binary
267 value ------------- Distribution ------------- count
269 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
272 firefox, func, moz_pis_startstop_scripts
273 value ------------- Distribution ------------- count
275 256 |@@@@@@@@@@@@@@@@@@@@ 1
282 32768 |@@@@@@@@@@@@@@@@@@@@ 1
285 run-mozilla.sh, func, moz_run_program
286 value ------------- Distribution ------------- count
288 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
292 As an example of interpreting the output: the inclusive elapsed time for
293 the "[" (test) builtin,
296 value ------------- Distribution ------------- count
307 shows that it was called 17 times (after adding up the counts), 5 of which
308 took between 16 and 31 microseconds.