cddl/contrib/dtracetoolkit/Notes/ALLexclusive_notes.txt

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