1N/A**************************************************************************
1N/A* Notes for all scripts that print exclusive function times (or method,
1N/A* or subroutine).
1N/A*
1N/A* $Id: ALLexclusive_notes.txt 45 2007-09-17 08:54:56Z brendan $
1N/A*
1N/A* COPYRIGHT: Copyright (c) 2007 Brendan Gregg.
1N/A**************************************************************************
1N/A
1N/A
1N/A* What is "exclusive" function time?
1N/A
1N/AThis is the time of function execution, from when the function begins to
1N/Awhen it completes, excluding the time spent executing any child function.
1N/A
1N/AExclusive function time can be calculated like this,
1N/A
1N/A exclusive function time = time(function end) - time(function start) -
1N/A time(total child exclusive time)
1N/A
1N/ATo do this, the DTrace script needs to keep trace of child function execution
1N/Atime, so that it can be subtracted from the parent execution time.
1N/A
1N/AConsider this Bourne shell program,
1N/A 1 #!./sh
1N/A 2
1N/A 3 func_c()
1N/A 4 {
1N/A 5 echo "Function C"
1N/A 6 sleep 1
1N/A 7 }
1N/A 8
1N/A 9 func_b()
1N/A 10 {
1N/A 11 echo "Function B"
1N/A 12 sleep 1
1N/A 13 func_c
1N/A 14 }
1N/A 15
1N/A 16 func_a()
1N/A 17 {
1N/A 18 echo "Function A"
1N/A 19 sleep 1
1N/A 20 func_b
1N/A 21 }
1N/A 22
1N/A 23 func_a
1N/A
1N/Afunc_a() calls func_b() which calls func_c(). Tracing the flow using
1N/Ash_flowtime.d shows,
1N/A
1N/A# ./sh_flowtime.d | cat -n
1N/A 1 C TIME(us) FILE DELTA(us) -- NAME
1N/A 2 0 3052991099265 func_abc.sh 2 -> func_a
1N/A 3 0 3052991099324 func_abc.sh 59 > echo
1N/A 4 0 3052992111638 func_abc.sh 1012314 | sleep
1N/A 5 0 3052992111678 func_abc.sh 39 -> func_b
1N/A 6 0 3052992111729 func_abc.sh 51 > echo
1N/A 7 0 3052993121633 func_abc.sh 1009903 | sleep
1N/A 8 0 3052993121693 func_abc.sh 60 -> func_c
1N/A 9 0 3052993121745 func_abc.sh 52 > echo
1N/A 10 0 3052994131634 func_abc.sh 1009888 | sleep
1N/A 11 0 3052994131685 func_abc.sh 50 <- func_c
1N/A 12 0 3052994131699 func_abc.sh 14 <- func_b
1N/A 13 0 3052994131707 func_abc.sh 7 <- func_a
1N/A
1N/Athe output of DTrace was piped through "cat -n" to enumerate the lines.
1N/A
1N/AExclusive function time for func_a() in the above output would be the
1N/Atime from line 2 to line 13 minus the time from line 5 to 12 to subtract
1N/Athe time spent in both func_b() and func_c(). Or, you could say that
1N/Aexclusive time for func_a() is the time from lines 2 to 4.
1N/A
1N/ALooking back at the code, exclusive time for func_a() is the time spent
1N/Ain code lines 18 and 19 (and not line 20).
1N/A
1N/ASee Notes/ALLinclusive_notes.txt for details on "inclusive" function time.
1N/A