cddl/contrib/dtracetoolkit/Notes/ALLinclusive_notes.txt

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