xref: /netbsd-src/external/cddl/dtracetoolkit/dist/Docs/Examples/tcl_cputime_example.txt (revision c29d51755812ace2e87aeefdb06cb2b4dac7087a)
1Following are examples of running tcl_cputime.d.
2
3Here it runs while we execute Code/Tcl/func_slow.tcl
4
5# tcl_cputime.d
6Tracing... Hit Ctrl-C to end.
7^C
8
9Top 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
22Top 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
35Top 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
48We can see that the output is in three sections.  The first section represents
49the ten most commonly executed commands while the script is tracing.
50
51The exclusive function on-CPU times show that func_a spent around 0.5 seconds
52on-CPU, func_b spent about 1.0 seconds, and func_c, 1.6 seconds. This excludes
53time spent in other procedures or commands.
54
55The inclusive function on-CPU times show the time spent by these procedures in
56total, including the time spent in other functions called, and since func_a
57called func_b which called func_c, these times make sense.
58
59These on-CPU times are the time the thread spent running on a CPU, from when
60the function began to when it completed. This does not include time
61spent off-CPU time such as sleeping for I/O or waiting for scheduling.
62
63On-CPU times are useful for showing who is causing the CPUs to be busy.
64See Notes/ALLoncpu_notes.txt for more details. Also see
65Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
66detailed explanation of exclusive vs inclusive function time.
67
68