xref: /netbsd-src/external/cddl/dtracetoolkit/dist/Examples/php_calltime_example.txt (revision c29d51755812ace2e87aeefdb06cb2b4dac7087a)
1The following is an example of running php_calltime.d and tracing the elapsed
2times for functions.
3
4We run php_calltime.d while running the program Code/Php/func_abc.php.  We can
5see that there are three sections in the DTrace output
6
7# php_calltime.d
8Tracing... Hit Ctrl-C to end.
9^C
10
11Count,
12   FILE                 TYPE       NAME                                COUNT
13   func_abc.php         func       func_a                                  1
14   func_abc.php         func       func_b                                  1
15   func_abc.php         func       func_c                                  1
16   func_abc.php         func       sleep                                   3
17   -                    total      -                                       6
18
19Exclusive function elapsed times (us),
20   FILE                 TYPE       NAME                                TOTAL
21   func_abc.php         func       func_c                                330
22   func_abc.php         func       func_b                                367
23   func_abc.php         func       func_a                                418
24   func_abc.php         func       sleep                             3025644
25   -                    total      -                                 3026761
26
27Inclusive function elapsed times (us),
28   FILE                 TYPE       NAME                                TOTAL
29   func_abc.php         func       func_c                            1010119
30   func_abc.php         func       func_b                            2020118
31   func_abc.php         func       sleep                             3025644
32   func_abc.php         func       func_a                            3026761
33
34Section 1 - Count shows us how many times each function was called in the
35Code/Php/func_abc.php program, with the last line giving us a total number of
36functions called (in this case, six).
37
38Section 2 - These elapsed times shows us how many microseconds the program
39spends in each function.  This does not include the time spent in any
40sub-functions called by that particular function.  Again the last line gives
41us the total time in microseconds.
42
43Section 3 - These elapsed times are the absolute time from when the function began to
44when it completed - which includes off-CPU time due to other system events
45such as I/O, scheduling, interrupts, etc. In particular, for this case it has
46included the time waiting for the sleep commands.
47
48Elapsed times are useful for identifying where latencies are.
49See Notes/ALLelapsed_notes.txt for more details. Also see
50Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
51detailed explanation of exclusive vs inclusive function time.
52