share/doc/papers/kerntune/2.t

   1 .\" Copyright (c) 1984 M. K. McKusick
   2 .\" Copyright (c) 1984 The Regents of the University of California.
   3 .\" All rights reserved.
   4 .\"
   5 .\" Redistribution and use in source and binary forms, with or without
   6 .\" modification, are permitted provided that the following conditions
   7 .\" are met:
   8 .\" 1. Redistributions of source code must retain the above copyright
   9 .\"    notice, this list of conditions and the following disclaimer.
  10 .\" 2. Redistributions in binary form must reproduce the above copyright
  11 .\"    notice, this list of conditions and the following disclaimer in the
  12 .\"    documentation and/or other materials provided with the distribution.
  13 .\" 3. Neither the name of the University nor the names of its contributors
  14 .\"    may be used to endorse or promote products derived from this software
  15 .\"    without specific prior written permission.
  16 .\"
  17 .\" THIS SOFTWARE IS PROVIDED BY THE REGENTS AND CONTRIBUTORS ``AS IS'' AND
  18 .\" ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
  19 .\" IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
  20 .\" ARE DISCLAIMED.  IN NO EVENT SHALL THE REGENTS OR CONTRIBUTORS BE LIABLE
  21 .\" FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
  22 .\" DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
  23 .\" OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
  24 .\" HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
  25 .\" LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
  26 .\" OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
  27 .\" SUCH DAMAGE.
  28 .\"
  29 .\"     @(#)2.t 1.3 (Berkeley) 11/8/90
  30 .\"
  31 .ds RH The \fIgprof\fP Profiler
  32 .NH 1
  33 The \fIgprof\fP Profiler
  34 .PP
  35 The purpose of the \fIgprof\fP profiling tool is to
  36 help the user evaluate alternative implementations
  37 of abstractions.
  38 The \fIgprof\fP design takes advantage of the fact that the kernel
  39 though large, is structured and hierarchical.
  40 We provide a profile in which the execution time
  41 for a set of routines that implement an
  42 abstraction is collected and charged
  43 to that abstraction.
  44 The profile can be used to compare and assess the costs of
  45 various implementations [Graham82] [Graham83].
  46 .NH 2
  47 Data presentation
  48 .PP
  49 The data is presented to the user in two different formats.
  50 The first presentation simply lists the routines
  51 without regard to the amount of time their descendants use.
  52 The second presentation incorporates the call graph of the
  53 kernel.
  54 .NH 3
  55 The Flat Profile
  56 .PP
  57 The flat profile consists of a list of all the routines
  58 that are called during execution of the kernel,
  59 with the count of the number of times they are called
  60 and the number of seconds of execution time for which they
  61 are themselves accountable.
  62 The routines are listed in decreasing order of execution time.
  63 A list of the routines that are never called during execution of
  64 the kernel is also available
  65 to verify that nothing important is omitted by
  66 this profiling run.
  67 The flat profile gives a quick overview of the routines that are used,
  68 and shows the routines that are themselves responsible
  69 for large fractions of the execution time.
  70 In practice,
  71 this profile usually shows that no single function
  72 is overwhelmingly responsible for
  73 the total time of the kernel.
  74 Notice that for this profile,
  75 the individual times sum to the total execution time.
  76 .NH 3
  77 The Call Graph Profile
  78 .PP
  79 Ideally, we would like to print the call graph of the kernel,
  80 but we are limited by the two-dimensional nature of our output
  81 devices.
  82 We cannot assume that a call graph is planar,
  83 and even if it is, that we can print a planar version of it.
  84 Instead, we choose to list each routine,
  85 together with information about
  86 the routines that are its direct parents and children.
  87 This listing presents a window into the call graph.
  88 Based on our experience,
  89 both parent information and child information
  90 is important,
  91 and should be available without searching
  92 through the output.
  93 Figure 1 shows a sample \fIgprof\fP entry.
  94 .KF
  95 .DS L
  96 .TS
  97 box center;
  98 c c c c c l l
  99 c c c c c l l
 100 c c c c c l l
 101 l n n n c l l.
 102                                 called/total    \ \ parents
 103 index   %time   self    descendants     called+self     name    index
 104                                 called/total    \ \ children
 105 _
 106                 0.20    1.20    4/10    \ \ \s-1CALLER1\s+1     [7]
 107                 0.30    1.80    6/10    \ \ \s-1CALLER2\s+1     [1]
 108 [2]     41.5    0.50    3.00    10+4    \s-1EXAMPLE\s+1 [2]
 109                 1.50    1.00    20/40   \ \ \s-1SUB1\s+1 <cycle1>       [4]
 110                 0.00    0.50    1/5     \ \ \s-1SUB2\s+1        [9]
 111                 0.00    0.00    0/5     \ \ \s-1SUB3\s+1        [11]
 112 .TE
 113 .ce
 114 Figure 1. Profile entry for \s-1EXAMPLE\s+1.
 115 .DE
 116 .KE
 117 .PP
 118 The major entries of the call graph profile are the entries from the
 119 flat profile, augmented by the time propagated to each
 120 routine from its descendants.
 121 This profile is sorted by the sum of the time for the routine
 122 itself plus the time inherited from its descendants.
 123 The profile shows which of the higher level routines
 124 spend large portions of the total execution time
 125 in the routines that they call.
 126 For each routine, we show the amount of time passed by each child
 127 to the routine, which includes time for the child itself
 128 and for the descendants of the child
 129 (and thus the descendants of the routine).
 130 We also show the percentage these times represent of the total time
 131 accounted to the child.
 132 Similarly, the parents of each routine are listed,
 133 along with time,
 134 and percentage of total routine time,
 135 propagated to each one.
 136 .PP
 137 Cycles are handled as single entities.
 138 The cycle as a whole is shown as though it were a single routine,
 139 except that members of the cycle are listed in place of the children.
 140 Although the number of calls of each member
 141 from within the cycle are shown,
 142 they do not affect time propagation.
 143 When a child is a member of a cycle,
 144 the time shown is the appropriate fraction of the time
 145 for the whole cycle.
 146 Self-recursive routines have their calls broken
 147 down into calls from the outside and self-recursive calls.
 148 Only the outside calls affect the propagation of time.
 149 .PP
 150 The example shown in Figure 2 is the fragment of a call graph
 151 corresponding to the entry in the call graph profile listing
 152 shown in Figure 1.
 153 .KF
 154 .DS L
 155 .so fig2.pic
 156 .ce
 157 Figure 2. Example call graph fragment.
 158 .DE
 159 .KE
 160 .PP
 161 The entry is for routine \s-1EXAMPLE\s+1, which has
 162 the Caller routines as its parents,
 163 and the Sub routines as its children.
 164 The reader should keep in mind that all information
 165 is given \fIwith respect to \s-1EXAMPLE\s+1\fP.
 166 The index in the first column shows that \s-1EXAMPLE\s+1
 167 is the second entry in the profile listing.
 168 The \s-1EXAMPLE\s+1 routine is called ten times, four times by \s-1CALLER1\s+1,
 169 and six times by \s-1CALLER2\s+1.
 170 Consequently 40% of \s-1EXAMPLE\s+1's time is propagated to \s-1CALLER1\s+1,
 171 and 60% of \s-1EXAMPLE\s+1's time is propagated to \s-1CALLER2\s+1.
 172 The self and descendant fields of the parents
 173 show the amount of self and descendant time \s-1EXAMPLE\s+1
 174 propagates to them (but not the time used by
 175 the parents directly).
 176 Note that \s-1EXAMPLE\s+1 calls itself recursively four times.
 177 The routine \s-1EXAMPLE\s+1 calls routine \s-1SUB1\s+1 twenty times, \s-1SUB2\s+1 once,
 178 and never calls \s-1SUB3\s+1.
 179 Since \s-1SUB2\s+1 is called a total of five times,
 180 20% of its self and descendant time is propagated to \s-1EXAMPLE\s+1's
 181 descendant time field.
 182 Because \s-1SUB1\s+1 is a member of \fIcycle 1\fR,
 183 the self and descendant times
 184 and call count fraction
 185 are those for the cycle as a whole.
 186 Since cycle 1 is called a total of forty times
 187 (not counting calls among members of the cycle),
 188 it propagates 50% of the cycle's self and descendant
 189 time to \s-1EXAMPLE\s+1's descendant time field.
 190 Finally each name is followed by an index that shows
 191 where on the listing to find the entry for that routine.
 192 .NH 2
 193 Profiling the Kernel
 194 .PP
 195 It is simple to build a 4.2BSD kernel that will automatically
 196 collect profiling information as it operates simply by specifying the
 197 .B \-p
 198 option to \fIconfig\fP\|(8) when configuring a kernel.
 199 The program counter sampling can be driven by the system clock,
 200 or by an alternate real time clock.
 201 The latter is highly recommended as use of the system clock results
 202 in statistical anomalies in accounting for
 203 the time spent in the kernel clock routine.
 204 .PP
 205 Once a profiling system has been booted statistic gathering is
 206 handled by \fIkgmon\fP\|(8).
 207 \fIKgmon\fP allows profiling to be started and stopped
 208 and the internal state of the profiling buffers to be dumped.
 209 \fIKgmon\fP can also be used to reset the state of the internal
 210 buffers to allow multiple experiments to be run without
 211 rebooting the machine.
 212 The profiling data can then be processed with \fIgprof\fP\|(1)
 213 to obtain information regarding the system's operation.
 214 .PP
 215 A profiled system is about 5-10% larger in its text space because of
 216 the calls to count the subroutine invocations.
 217 When the system executes,
 218 the profiling data is stored in a buffer that is 1.2
 219 times the size of the text space.
 220 All the information is summarized in memory,
 221 it is not necessary to have a trace file
 222 being continuously dumped to disk.
 223 The overhead for running a profiled system varies;
 224 under normal load we see anywhere from 5-25%
 225 of the system time spent in the profiling code.
 226 Thus the system is noticeably slower than an unprofiled system,
 227 yet is not so bad that it cannot be used in a production environment.
 228 This is important since it allows us to gather data
 229 in a real environment rather than trying to
 230 devise synthetic work loads.