1The following are examples of sh_cputime.d. 2 3This script traces the on-CPU time of Bourne shell functions and 4prints a report. Here it traces the example program, Code/Shell/func_slow.sh. 5 6 # sh_cputime.d 7 Tracing... Hit Ctrl-C to end. 8 ^C 9 10 Counts, 11 FILE TYPE NAME COUNT 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 17 - total - 609 18 19 On-CPU times (us), 20 FILE TYPE NAME TOTAL 21 func_slow.sh builtin echo 162 22 func_slow.sh builtin [ 6279 23 - total - 6441 24 25 Exclusive function on-CPU times (us), 26 FILE TYPE NAME TOTAL 27 func_slow.sh func func_a 269465 28 func_slow.sh func func_b 670372 29 func_slow.sh func func_c 1259073 30 - total - 2198911 31 32 Inclusive function on-CPU times (us), 33 FILE TYPE NAME TOTAL 34 func_slow.sh func func_c 1262209 35 func_slow.sh func func_b 1934839 36 func_slow.sh func func_a 2205352 37 38In total, three functions were called, one builtin and one command. 39 40The exclusive function on-CPU times show that func_a() spent around 268.4 ms 41on-CPU, func_b() spent 670.3 ms, and func_c() spent 1259 ms. This exclusive 42times excludes time spent in other functions. 43 44The inclusive function on-CPU times show that func_c() spent around 1.3 45seconds on-CPU, func_b() spent around 1.9 seconds, and func_a() spent around 462.2 seconds. This inclusive time includes the time spent in other functions 47called, and since func_a() called func_b() which called func_c(), these 48times make sense. 49 50These on-CPU times are the time the thread spent running on a CPU, from when 51the function began to when it completed. This does not include time 52spent off-CPU time such as sleeping for I/O or waiting for scheduling. 53 54On-CPU times are useful for showing who is causing the CPUs to be busy. 55See Notes/ALLoncpu_notes.txt for more details. Also see 56Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 57detailed explanation of exclusive vs inclusive function time. 58 59If you study the func_slow.sh program alongside the above output, the numbers 60should make sense. 61 62 63 64The following traced the firefox start script. 65 66# sh_cputime.d 67Tracing... Hit Ctrl-C to end. 68^C 69 70Counts, 71 FILE TYPE NAME COUNT 72 firefox builtin break 1 73 firefox builtin pwd 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 85 firefox builtin cd 3 86 firefox builtin export 3 87 run-mozilla.sh builtin export 3 88 firefox builtin : 6 89 firefox func moz_spc_verbose_echo 6 90 firefox builtin [ 18 91 run-mozilla.sh builtin [ 20 92 - total - 103 93 94On-CPU times (us), 95 FILE TYPE NAME TOTAL 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 102 firefox builtin : 9 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 112 - total - 1950979 113 114Exclusive function on-CPU times (us), 115 FILE TYPE NAME TOTAL 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 120 - total - 22103 121 122Inclusive function on-CPU times (us), 123 FILE TYPE NAME TOTAL 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 128 129The output showed that the most CPU time was spent in the firefox-bin command, 130taking 1.9 seconds of on-CPU time. 131 132