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