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.
|