xref: /netbsd-src/external/cddl/dtracetoolkit/dist/Docs/Examples/php_flowtime_example.txt (revision c29d51755812ace2e87aeefdb06cb2b4dac7087a)
1*c29d5175SchristosThe following are examples of php_flowtime.d.
2*c29d5175Schristos
3*c29d5175SchristosThis is a simple script to trace the flow of PHP functions.
4*c29d5175SchristosHere it traces the example program, Code/Php/func_abc.php
5*c29d5175Schristos
6*c29d5175Schristos# php_flowtime.d
7*c29d5175Schristos  C TIME(us)         FILE             DELTA(us)  -- FUNC
8*c29d5175Schristos  0 3646108339057    func_abc.php             9 -> func_a
9*c29d5175Schristos  0 3646108339090    func_abc.php            32   -> sleep
10*c29d5175Schristos  0 3646109341043    func_abc.php       1001953   <- sleep
11*c29d5175Schristos  0 3646109341074    func_abc.php            31   -> func_b
12*c29d5175Schristos  0 3646109341098    func_abc.php            23     -> sleep
13*c29d5175Schristos  0 3646110350712    func_abc.php       1009614     <- sleep
14*c29d5175Schristos  0 3646110350745    func_abc.php            32     -> func_c
15*c29d5175Schristos  0 3646110350768    func_abc.php            23       -> sleep
16*c29d5175Schristos  0 3646111362323    func_abc.php       1011554       <- sleep
17*c29d5175Schristos  0 3646111362351    func_abc.php            27     <- func_c
18*c29d5175Schristos  0 3646111362361    func_abc.php            10   <- func_b
19*c29d5175Schristos  0 3646111362370    func_abc.php             9 <- func_a
20*c29d5175Schristos^C
21*c29d5175Schristos
22*c29d5175SchristosThe fifth column is indented by 2 spaces to show when a new function begins.
23*c29d5175SchristosThis shows which function is calling which - the output above begins by
24*c29d5175Schristosshowing that func_a() began; slept, and returned from sleep; and then called
25*c29d5175Schristosfunc_b().
26*c29d5175Schristos
27*c29d5175SchristosThe TIME(us) column shows time since boot.
28*c29d5175Schristos
29*c29d5175SchristosThe DELTA(us) column shows time from that line to the previous line, and
30*c29d5175Schristosso can be a bit tricky to read. For example, the second line of data output
31*c29d5175Schristos(skipping the header) reads as "the time from func_a() beginning to
32*c29d5175Schristoscalling the sleep function beginning was 32 microseconds".
33*c29d5175Schristos
34*c29d5175SchristosThe FILE column shows file that was being executed.
35*c29d5175Schristos
36*c29d5175SchristosIf the output looks shuffled, check the CPU "C" and "TIME" columns, and
37*c29d5175Schristospost sort based on TIME if necessary.
38*c29d5175Schristos
39*c29d5175SchristosSee Notes/ALLflow_notes.txt for important notes about reading flow outputs.
40*c29d5175Schristos
41*c29d5175Schristos
42