1 The following are examples of sh_cputime.d.
3 This script traces the on-CPU time of Bourne shell functions and
4 prints a report. Here it traces the example program, Code/Shell/func_slow.sh.
7 Tracing... Hit Ctrl-C to end.
12 func_slow.sh func func_a 1
13 func_slow.sh func func_b 1
14 func_slow.sh func func_c 1
15 func_slow.sh builtin echo 3
16 func_slow.sh builtin [ 603
21 func_slow.sh builtin echo 162
22 func_slow.sh builtin [ 6279
25 Exclusive function on-CPU times (us),
27 func_slow.sh func func_a 269465
28 func_slow.sh func func_b 670372
29 func_slow.sh func func_c 1259073
32 Inclusive function on-CPU times (us),
34 func_slow.sh func func_c 1262209
35 func_slow.sh func func_b 1934839
36 func_slow.sh func func_a 2205352
38 In total, three functions were called, one builtin and one command.
40 The exclusive function on-CPU times show that func_a() spent around 268.4 ms
41 on-CPU, func_b() spent 670.3 ms, and func_c() spent 1259 ms. This exclusive
42 times excludes time spent in other functions.
44 The inclusive function on-CPU times show that func_c() spent around 1.3
45 seconds on-CPU, func_b() spent around 1.9 seconds, and func_a() spent around
46 2.2 seconds. This inclusive time includes the time spent in other functions
47 called, and since func_a() called func_b() which called func_c(), these
50 These on-CPU times are the time the thread spent running on a CPU, from when
51 the function began to when it completed. This does not include time
52 spent off-CPU time such as sleeping for I/O or waiting for scheduling.
54 On-CPU times are useful for showing who is causing the CPUs to be busy.
55 See Notes/ALLoncpu_notes.txt for more details. Also see
56 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
57 detailed explanation of exclusive vs inclusive function time.
59 If you study the func_slow.sh program alongside the above output, the numbers
64 The following traced the firefox start script.
67 Tracing... Hit Ctrl-C to end.
72 firefox builtin break 1
74 firefox builtin test 1
75 firefox cmd run-mozilla.sh 1
76 run-mozilla.sh builtin break 1
77 run-mozilla.sh builtin return 1
78 run-mozilla.sh builtin shift 1
79 run-mozilla.sh builtin type 1
80 run-mozilla.sh cmd firefox-bin 1
81 run-mozilla.sh func moz_run_program 1
82 run-mozilla.sh func moz_test_binary 1
83 firefox builtin echo 2
84 firefox func moz_pis_startstop_scripts 2
86 firefox builtin export 3
87 run-mozilla.sh builtin export 3
89 firefox func moz_spc_verbose_echo 6
91 run-mozilla.sh builtin [ 20
96 run-mozilla.sh builtin return 0
97 run-mozilla.sh builtin shift 0
98 run-mozilla.sh builtin break 1
99 firefox builtin break 2
100 run-mozilla.sh builtin export 4
101 firefox builtin export 7
103 firefox builtin test 35
104 firefox builtin pwd 49
105 firefox builtin cd 64
106 run-mozilla.sh builtin [ 176
107 firefox builtin echo 309
108 firefox builtin [ 357
109 run-mozilla.sh builtin type 475
110 firefox cmd run-mozilla.sh 17090
111 run-mozilla.sh cmd firefox-bin 1932333
114 Exclusive function on-CPU times (us),
116 run-mozilla.sh func moz_test_binary 21
117 firefox func moz_spc_verbose_echo 22
118 run-mozilla.sh func moz_run_program 9098
119 firefox func moz_pis_startstop_scripts 12960
122 Inclusive function on-CPU times (us),
124 firefox func moz_spc_verbose_echo 31
125 run-mozilla.sh func moz_test_binary 56
126 run-mozilla.sh func moz_run_program 9243
127 firefox func moz_pis_startstop_scripts 13133
129 The output showed that the most CPU time was spent in the firefox-bin command,
130 taking 1.9 seconds of on-CPU time.