cddl/contrib/dtracetoolkit/Examples/tcl_cputime_example.txt

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