blob: 7aeb9ffde84c625e8ab679a527e662f07eba59d8 (
plain)
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
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
|
**************************************************************************
* Notes for all scripts that print exclusive function times (or method,
* or subroutine).
*
* $Id: ALLexclusive_notes.txt 45 2007-09-17 08:54:56Z brendan $
*
* COPYRIGHT: Copyright (c) 2007 Brendan Gregg.
**************************************************************************
* What is "exclusive" function time?
This is the time of function execution, from when the function begins to
when it completes, excluding the time spent executing any child function.
Exclusive function time can be calculated like this,
exclusive function time = time(function end) - time(function start) -
time(total child exclusive time)
To do this, the DTrace script needs to keep trace of child function execution
time, so that it can be subtracted from the parent execution time.
Consider this Bourne shell program,
1 #!./sh
2
3 func_c()
4 {
5 echo "Function C"
6 sleep 1
7 }
8
9 func_b()
10 {
11 echo "Function B"
12 sleep 1
13 func_c
14 }
15
16 func_a()
17 {
18 echo "Function A"
19 sleep 1
20 func_b
21 }
22
23 func_a
func_a() calls func_b() which calls func_c(). Tracing the flow using
sh_flowtime.d shows,
# ./sh_flowtime.d | cat -n
1 C TIME(us) FILE DELTA(us) -- NAME
2 0 3052991099265 func_abc.sh 2 -> func_a
3 0 3052991099324 func_abc.sh 59 > echo
4 0 3052992111638 func_abc.sh 1012314 | sleep
5 0 3052992111678 func_abc.sh 39 -> func_b
6 0 3052992111729 func_abc.sh 51 > echo
7 0 3052993121633 func_abc.sh 1009903 | sleep
8 0 3052993121693 func_abc.sh 60 -> func_c
9 0 3052993121745 func_abc.sh 52 > echo
10 0 3052994131634 func_abc.sh 1009888 | sleep
11 0 3052994131685 func_abc.sh 50 <- func_c
12 0 3052994131699 func_abc.sh 14 <- func_b
13 0 3052994131707 func_abc.sh 7 <- func_a
the output of DTrace was piped through "cat -n" to enumerate the lines.
Exclusive function time for func_a() in the above output would be the
time from line 2 to line 13 minus the time from line 5 to 12 to subtract
the time spent in both func_b() and func_c(). Or, you could say that
exclusive time for func_a() is the time from lines 2 to 4.
Looking back at the code, exclusive time for func_a() is the time spent
in code lines 18 and 19 (and not line 20).
See Notes/ALLinclusive_notes.txt for details on "inclusive" function time.
|
