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