1 1.1 christos The following are examples of tcl_cpudist.d. 2 1.1 christos 3 1.1 christos This script traces the on-CPU time of Tcl commands and procedures and 4 1.1 christos prints a report containing distribution plots per subroutine. Here it 5 1.1 christos traces the example program, Code/Tcl/func_slow.tcl. 6 1.1 christos 7 1.1 christos # tcl_cpudist.d 8 1.1 christos Tracing... Hit Ctrl-C to end. 9 1.1 christos ^C 10 1.1 christos 11 1.1 christos Top 10 exclusive on-CPU times (us), 12 1.1 christos PID=16043, cmd, info 13 1.1 christos value ------------- Distribution ------------- count 14 1.1 christos 0 | 0 15 1.1 christos 1 |@@@@ 1 16 1.1 christos 2 |@@@@@@@@@@@@@@@ 4 17 1.1 christos 4 |@@@@ 1 18 1.1 christos 8 |@@@@ 1 19 1.1 christos 16 |@@@@@@@@@@@ 3 20 1.1 christos 32 |@@@@ 1 21 1.1 christos 64 | 0 22 1.1 christos 23 1.1 christos PID=16043, cmd, namespace 24 1.1 christos value ------------- Distribution ------------- count 25 1.1 christos 0 | 0 26 1.1 christos 1 |@@@@@@@@@@@@@ 1 27 1.1 christos 2 |@@@@@@@@@@@@@ 1 28 1.1 christos 4 | 0 29 1.1 christos 8 | 0 30 1.1 christos 16 | 0 31 1.1 christos 32 | 0 32 1.1 christos 64 | 0 33 1.1 christos 128 |@@@@@@@@@@@@@ 1 34 1.1 christos 256 | 0 35 1.1 christos 36 1.1 christos PID=16043, cmd, puts 37 1.1 christos value ------------- Distribution ------------- count 38 1.1 christos 16 | 0 39 1.1 christos 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 40 1.1 christos 64 | 0 41 1.1 christos 128 |@@@@@@@@@@@@@ 1 42 1.1 christos 256 | 0 43 1.1 christos 44 1.1 christos PID=16043, cmd, if 45 1.1 christos value ------------- Distribution ------------- count 46 1.1 christos 4 | 0 47 1.1 christos 8 |@@@@@@@@@@ 2 48 1.1 christos 16 |@@@@@@@@@@@@@@@@@@@@ 4 49 1.1 christos 32 |@@@@@ 1 50 1.1 christos 64 | 0 51 1.1 christos 128 |@@@@@ 1 52 1.1 christos 256 | 0 53 1.1 christos 54 1.1 christos PID=16043, cmd, tclInit 55 1.1 christos value ------------- Distribution ------------- count 56 1.1 christos 128 | 0 57 1.1 christos 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 58 1.1 christos 512 | 0 59 1.1 christos 60 1.1 christos PID=16043, cmd, file 61 1.1 christos value ------------- Distribution ------------- count 62 1.1 christos 2 | 0 63 1.1 christos 4 |@@@@@@@@@@@@@ 4 64 1.1 christos 8 |@@@@@@@@@@@@@ 4 65 1.1 christos 16 | 0 66 1.1 christos 32 |@@@ 1 67 1.1 christos 64 |@@@@@@@@@@ 3 68 1.1 christos 128 | 0 69 1.1 christos 70 1.1 christos PID=16043, cmd, source 71 1.1 christos value ------------- Distribution ------------- count 72 1.1 christos 256 | 0 73 1.1 christos 512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 74 1.1 christos 1024 | 0 75 1.1 christos 76 1.1 christos PID=16043, proc, func_a 77 1.1 christos value ------------- Distribution ------------- count 78 1.1 christos 262144 | 0 79 1.1 christos 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 80 1.1 christos 1048576 | 0 81 1.1 christos 82 1.1 christos PID=16043, proc, func_b 83 1.1 christos value ------------- Distribution ------------- count 84 1.1 christos 524288 | 0 85 1.1 christos 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 86 1.1 christos 2097152 | 0 87 1.1 christos 88 1.1 christos PID=16043, proc, func_c 89 1.1 christos value ------------- Distribution ------------- count 90 1.1 christos 524288 | 0 91 1.1 christos 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 92 1.1 christos 2097152 | 0 93 1.1 christos 94 1.1 christos 95 1.1 christos Top 10 inclusive on-CPU times (us), 96 1.1 christos PID=16043, cmd, source 97 1.1 christos value ------------- Distribution ------------- count 98 1.1 christos 512 | 0 99 1.1 christos 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 100 1.1 christos 2048 | 0 101 1.1 christos 102 1.1 christos PID=16043, cmd, uplevel 103 1.1 christos value ------------- Distribution ------------- count 104 1.1 christos 512 | 0 105 1.1 christos 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 106 1.1 christos 2048 | 0 107 1.1 christos 108 1.1 christos PID=16043, proc, tclInit 109 1.1 christos value ------------- Distribution ------------- count 110 1.1 christos 512 | 0 111 1.1 christos 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 112 1.1 christos 2048 | 0 113 1.1 christos 114 1.1 christos PID=16043, cmd, tclInit 115 1.1 christos value ------------- Distribution ------------- count 116 1.1 christos 1024 | 0 117 1.1 christos 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 118 1.1 christos 4096 | 0 119 1.1 christos 120 1.1 christos PID=16043, cmd, func_c 121 1.1 christos value ------------- Distribution ------------- count 122 1.1 christos 524288 | 0 123 1.1 christos 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 124 1.1 christos 2097152 | 0 125 1.1 christos 126 1.1 christos PID=16043, proc, func_c 127 1.1 christos value ------------- Distribution ------------- count 128 1.1 christos 524288 | 0 129 1.1 christos 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 130 1.1 christos 2097152 | 0 131 1.1 christos 132 1.1 christos PID=16043, cmd, func_a 133 1.1 christos value ------------- Distribution ------------- count 134 1.1 christos 1048576 | 0 135 1.1 christos 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 136 1.1 christos 4194304 | 0 137 1.1 christos 138 1.1 christos PID=16043, cmd, func_b 139 1.1 christos value ------------- Distribution ------------- count 140 1.1 christos 1048576 | 0 141 1.1 christos 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 142 1.1 christos 4194304 | 0 143 1.1 christos 144 1.1 christos PID=16043, proc, func_a 145 1.1 christos value ------------- Distribution ------------- count 146 1.1 christos 1048576 | 0 147 1.1 christos 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 148 1.1 christos 4194304 | 0 149 1.1 christos 150 1.1 christos PID=16043, proc, func_b 151 1.1 christos value ------------- Distribution ------------- count 152 1.1 christos 1048576 | 0 153 1.1 christos 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 154 1.1 christos 4194304 | 0 155 1.1 christos 156 1.1 christos These on-CPU times are the time the thread spent running on a CPU, from when 157 1.1 christos the subroutine began to when it completed. This does not include time 158 1.1 christos spent off-CPU time such as sleeping for I/O or waiting for scheduling. 159 1.1 christos 160 1.1 christos On-CPU times are useful for showing who is causing the CPUs to be busy. 161 1.1 christos See Notes/ALLoncpu_notes.txt for more details. Also see 162 1.1 christos Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 163 1.1 christos detailed explanation of exclusive vs inclusive subroutine time. 164 1.1 christos 165