1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
|
The following are examples of sh_cputime.d.
This script traces the on-CPU time of Bourne shell functions and
prints a report. Here it traces the example program, Code/Shell/func_slow.sh.
# sh_cputime.d
Tracing... Hit Ctrl-C to end.
^C
Counts,
FILE TYPE NAME COUNT
func_slow.sh func func_a 1
func_slow.sh func func_b 1
func_slow.sh func func_c 1
func_slow.sh builtin echo 3
func_slow.sh builtin [ 603
- total - 609
On-CPU times (us),
FILE TYPE NAME TOTAL
func_slow.sh builtin echo 162
func_slow.sh builtin [ 6279
- total - 6441
Exclusive function on-CPU times (us),
FILE TYPE NAME TOTAL
func_slow.sh func func_a 269465
func_slow.sh func func_b 670372
func_slow.sh func func_c 1259073
- total - 2198911
Inclusive function on-CPU times (us),
FILE TYPE NAME TOTAL
func_slow.sh func func_c 1262209
func_slow.sh func func_b 1934839
func_slow.sh func func_a 2205352
In total, three functions were called, one builtin and one command.
The exclusive function on-CPU times show that func_a() spent around 268.4 ms
on-CPU, func_b() spent 670.3 ms, and func_c() spent 1259 ms. This exclusive
times excludes time spent in other functions.
The inclusive function on-CPU times show that func_c() spent around 1.3
seconds on-CPU, func_b() spent around 1.9 seconds, and func_a() spent around
2.2 seconds. This inclusive time includes the time spent in other functions
called, and since func_a() called func_b() which called func_c(), these
times make sense.
These on-CPU times are the time the thread spent running on a CPU, from when
the function began to when it completed. This does not include time
spent off-CPU time such as sleeping for I/O or waiting for scheduling.
On-CPU times are useful for showing who is causing the CPUs to be busy.
See Notes/ALLoncpu_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.
If you study the func_slow.sh program alongside the above output, the numbers
should make sense.
The following traced the firefox start script.
# sh_cputime.d
Tracing... Hit Ctrl-C to end.
^C
Counts,
FILE TYPE NAME COUNT
firefox builtin break 1
firefox builtin pwd 1
firefox builtin test 1
firefox cmd run-mozilla.sh 1
run-mozilla.sh builtin break 1
run-mozilla.sh builtin return 1
run-mozilla.sh builtin shift 1
run-mozilla.sh builtin type 1
run-mozilla.sh cmd firefox-bin 1
run-mozilla.sh func moz_run_program 1
run-mozilla.sh func moz_test_binary 1
firefox builtin echo 2
firefox func moz_pis_startstop_scripts 2
firefox builtin cd 3
firefox builtin export 3
run-mozilla.sh builtin export 3
firefox builtin : 6
firefox func moz_spc_verbose_echo 6
firefox builtin [ 18
run-mozilla.sh builtin [ 20
- total - 103
On-CPU times (us),
FILE TYPE NAME TOTAL
run-mozilla.sh builtin return 0
run-mozilla.sh builtin shift 0
run-mozilla.sh builtin break 1
firefox builtin break 2
run-mozilla.sh builtin export 4
firefox builtin export 7
firefox builtin : 9
firefox builtin test 35
firefox builtin pwd 49
firefox builtin cd 64
run-mozilla.sh builtin [ 176
firefox builtin echo 309
firefox builtin [ 357
run-mozilla.sh builtin type 475
firefox cmd run-mozilla.sh 17090
run-mozilla.sh cmd firefox-bin 1932333
- total - 1950979
Exclusive function on-CPU times (us),
FILE TYPE NAME TOTAL
run-mozilla.sh func moz_test_binary 21
firefox func moz_spc_verbose_echo 22
run-mozilla.sh func moz_run_program 9098
firefox func moz_pis_startstop_scripts 12960
- total - 22103
Inclusive function on-CPU times (us),
FILE TYPE NAME TOTAL
firefox func moz_spc_verbose_echo 31
run-mozilla.sh func moz_test_binary 56
run-mozilla.sh func moz_run_program 9243
firefox func moz_pis_startstop_scripts 13133
The output showed that the most CPU time was spent in the firefox-bin command,
taking 1.9 seconds of on-CPU time.
|
