1*c29d5175SchristosFollowing are examples of running tcl_cputime.d. 2*c29d5175Schristos 3*c29d5175SchristosHere it runs while we execute Code/Tcl/func_slow.tcl 4*c29d5175Schristos 5*c29d5175Schristos# tcl_cputime.d 6*c29d5175SchristosTracing... Hit Ctrl-C to end. 7*c29d5175Schristos^C 8*c29d5175Schristos 9*c29d5175SchristosTop 10 counts, 10*c29d5175Schristos PID TYPE NAME COUNT 11*c29d5175Schristos 16038 cmd set 2 12*c29d5175Schristos 16038 cmd namespace 3 13*c29d5175Schristos 16038 cmd puts 3 14*c29d5175Schristos 16038 cmd lappend 4 15*c29d5175Schristos 16038 cmd lsearch 4 16*c29d5175Schristos 16038 cmd if 8 17*c29d5175Schristos 16038 cmd info 11 18*c29d5175Schristos 16038 cmd file 12 19*c29d5175Schristos 16038 cmd proc 12 20*c29d5175Schristos 0 total - 82 21*c29d5175Schristos 22*c29d5175SchristosTop 10 exclusive on-CPU times (us), 23*c29d5175Schristos PID TYPE NAME TOTAL 24*c29d5175Schristos 16038 cmd namespace 130 25*c29d5175Schristos 16038 cmd puts 232 26*c29d5175Schristos 16038 cmd if 310 27*c29d5175Schristos 16038 cmd tclInit 315 28*c29d5175Schristos 16038 cmd file 411 29*c29d5175Schristos 16038 cmd source 760 30*c29d5175Schristos 16038 proc func_a 535521 31*c29d5175Schristos 16038 proc func_b 1071082 32*c29d5175Schristos 16038 proc func_c 1619323 33*c29d5175Schristos 0 total - 3228670 34*c29d5175Schristos 35*c29d5175SchristosTop 10 inclusive on-CPU times (us), 36*c29d5175Schristos PID TYPE NAME TOTAL 37*c29d5175Schristos 16038 cmd source 1359 38*c29d5175Schristos 16038 cmd uplevel 1367 39*c29d5175Schristos 16038 proc tclInit 1865 40*c29d5175Schristos 16038 cmd tclInit 2180 41*c29d5175Schristos 16038 proc func_c 1619360 42*c29d5175Schristos 16038 cmd func_c 1619404 43*c29d5175Schristos 16038 proc func_b 2690525 44*c29d5175Schristos 16038 cmd func_b 2690568 45*c29d5175Schristos 16038 proc func_a 3226247 46*c29d5175Schristos 16038 cmd func_a 3226275 47*c29d5175Schristos 48*c29d5175SchristosWe can see that the output is in three sections. The first section represents 49*c29d5175Schristosthe ten most commonly executed commands while the script is tracing. 50*c29d5175Schristos 51*c29d5175SchristosThe exclusive function on-CPU times show that func_a spent around 0.5 seconds 52*c29d5175Schristoson-CPU, func_b spent about 1.0 seconds, and func_c, 1.6 seconds. This excludes 53*c29d5175Schristostime spent in other procedures or commands. 54*c29d5175Schristos 55*c29d5175SchristosThe inclusive function on-CPU times show the time spent by these procedures in 56*c29d5175Schristostotal, including the time spent in other functions called, and since func_a 57*c29d5175Schristoscalled func_b which called func_c, these times make sense. 58*c29d5175Schristos 59*c29d5175SchristosThese on-CPU times are the time the thread spent running on a CPU, from when 60*c29d5175Schristosthe function began to when it completed. This does not include time 61*c29d5175Schristosspent off-CPU time such as sleeping for I/O or waiting for scheduling. 62*c29d5175Schristos 63*c29d5175SchristosOn-CPU times are useful for showing who is causing the CPUs to be busy. 64*c29d5175SchristosSee Notes/ALLoncpu_notes.txt for more details. Also see 65*c29d5175SchristosNotes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 66*c29d5175Schristosdetailed explanation of exclusive vs inclusive function time. 67*c29d5175Schristos 68