doc/ref/statprof.texi

   1 @c -*-texinfo-*-
   2 @c This is part of the GNU Guile Reference Manual.
   3 @c Copyright (C) 2013, 2015 Free Software Foundation, Inc.
   4 @c See the file guile.texi for copying conditions.
   5
   6 @node Statprof
   7 @section Statprof
   8
   9 @code{(statprof)} is a fairly simple statistical profiler for Guile.
  10
  11 A simple use of statprof would look like this:
  12
  13 @example
  14 (statprof-reset 0 50000 #t)
  15 (statprof-start)
  16 (do-something)
  17 (statprof-stop)
  18 (statprof-display)
  19 @end example
  20
  21 This would reset statprof, clearing all accumulated statistics, then
  22 start profiling, run some code, stop profiling, and finally display a
  23 gprof flat-style table of statistics which will look something like
  24 this:
  25
  26 @example
  27   %   cumulative      self              self    total
  28  time    seconds   seconds    calls  ms/call  ms/call  name
  29  35.29      0.23      0.23     2002     0.11     0.11  -
  30  23.53      0.15      0.15     2001     0.08     0.08  positive?
  31  23.53      0.15      0.15     2000     0.08     0.08  +
  32  11.76      0.23      0.08     2000     0.04     0.11  do-nothing
  33   5.88      0.64      0.04     2001     0.02     0.32  loop
  34   0.00      0.15      0.00        1     0.00   150.59  do-something
  35  ...
  36 @end example
  37
  38 All of the numerical data with the exception of the calls column is
  39 statistically approximate. In the following column descriptions, and in
  40 all of statprof, "time" refers to execution time (both user and system),
  41 not wall clock time.
  42
  43 @table @asis
  44 @item % time
  45 The percent of the time spent inside the procedure itself (not counting
  46 children).
  47
  48 @item cumulative seconds
  49 The total number of seconds spent in the procedure, including children.
  50
  51 @item self seconds
  52 The total number of seconds spent in the procedure itself (not counting
  53 children).
  54
  55 @item calls
  56 The total number of times the procedure was called.
  57
  58 @item self ms/call
  59 The average time taken by the procedure itself on each call, in ms.
  60
  61 @item total ms/call
  62 The average time taken by each call to the procedure, including time
  63 spent in child functions.
  64
  65 @item name
  66 The name of the procedure.
  67
  68 @end table
  69
  70 The profiler uses @code{eq?} and the procedure object itself to identify
  71 the procedures, so it won't confuse different procedures with the same
  72 name. They will show up as two different rows in the output.
  73
  74 Right now the profiler is quite simplistic. I cannot provide call-graphs
  75 or other higher level information. What you see in the table is pretty
  76 much all there is. Patches are welcome :-)
  77
  78 @section Implementation notes
  79 The profiler works by setting the unix profiling signal
  80 @code{ITIMER_PROF} to go off after the interval you define in the call
  81 to @code{statprof-reset}. When the signal fires, a sampling routine is
  82 run which looks at the current procedure that's executing, and then
  83 crawls up the stack, and for each procedure encountered, increments that
  84 procedure's sample count. Note that if a procedure is encountered
  85 multiple times on a given stack, it is only counted once. After the
  86 sampling is complete, the profiler resets profiling timer to fire again
  87 after the appropriate interval.
  88
  89 Meanwhile, the profiler keeps track, via @code{get-internal-run-time},
  90 how much CPU time (system and user -- which is also what
  91 @code{ITIMER_PROF} tracks), has elapsed while code has been executing
  92 within a statprof-start/stop block.
  93
  94 The profiler also tries to avoid counting or timing its own code as much
  95 as possible.
  96
  97 @section Usage
  98 @anchor{statprof statprof-active?}@defun statprof-active?
  99 Returns @code{#t} if @code{statprof-start} has been called more times
 100 than @code{statprof-stop}, @code{#f} otherwise.
 101
 102 @end defun
 103
 104 @anchor{statprof statprof-start}@defun statprof-start
 105 Start the profiler.@code{}
 106
 107 @end defun
 108
 109 @anchor{statprof statprof-stop}@defun statprof-stop
 110 Stop the profiler.@code{}
 111
 112 @end defun
 113
 114 @anchor{statprof statprof-reset}@defun statprof-reset sample-seconds sample-microseconds count-calls? [full-stacks?]
 115 Reset the statprof sampler interval to @var{sample-seconds} and
 116 @var{sample-microseconds}. If @var{count-calls?} is true, arrange to
 117 instrument procedure calls as well as collecting statistical profiling
 118 data. If @var{full-stacks?} is true, collect all sampled stacks into a
 119 list for later analysis.
 120
 121 Enables traps and debugging as necessary.
 122
 123 @end defun
 124
 125 @anchor{statprof statprof-accumulated-time}@defun statprof-accumulated-time
 126 Returns the time accumulated during the last statprof run.@code{}
 127
 128 @end defun
 129
 130 @anchor{statprof statprof-sample-count}@defun statprof-sample-count
 131 Returns the number of samples taken during the last statprof run.@code{}
 132
 133 @end defun
 134
 135 @anchor{statprof statprof-fold-call-data}@defun statprof-fold-call-data proc init
 136 Fold @var{proc} over the call-data accumulated by statprof. Cannot be
 137 called while statprof is active. @var{proc} should take two arguments,
 138 @code{(@var{call-data} @var{prior-result})}.
 139
 140 Note that a given proc-name may appear multiple times, but if it does,
 141 it represents different functions with the same name.
 142
 143 @end defun
 144
 145 @anchor{statprof statprof-proc-call-data}@defun statprof-proc-call-data proc
 146 Returns the call-data associated with @var{proc}, or @code{#f} if none
 147 is available.
 148
 149 @end defun
 150
 151 @anchor{statprof statprof-call-data-name}@defun statprof-call-data-name cd
 152 @end defun
 153
 154 @anchor{statprof statprof-call-data-calls}@defun statprof-call-data-calls cd
 155 @end defun
 156
 157 @anchor{statprof statprof-call-data-cum-samples}@defun statprof-call-data-cum-samples cd
 158 @end defun
 159
 160 @anchor{statprof statprof-call-data-self-samples}@defun statprof-call-data-self-samples cd
 161 @end defun
 162
 163 @anchor{statprof statprof-call-data->stats}@defun statprof-call-data->stats call-data
 164 Returns an object of type @code{statprof-stats}.
 165
 166 @end defun
 167
 168 @anchor{statprof statprof-stats-proc-name}@defun statprof-stats-proc-name stats
 169 @end defun
 170
 171 @anchor{statprof statprof-stats-%-time-in-proc}@defun statprof-stats-%-time-in-proc stats
 172 @end defun
 173
 174 @anchor{statprof statprof-stats-cum-secs-in-proc}@defun statprof-stats-cum-secs-in-proc stats
 175 @end defun
 176
 177 @anchor{statprof statprof-stats-self-secs-in-proc}@defun statprof-stats-self-secs-in-proc stats
 178 @end defun
 179
 180 @anchor{statprof statprof-stats-calls}@defun statprof-stats-calls stats
 181 @end defun
 182
 183 @anchor{statprof statprof-stats-self-secs-per-call}@defun statprof-stats-self-secs-per-call stats
 184 @end defun
 185
 186 @anchor{statprof statprof-stats-cum-secs-per-call}@defun statprof-stats-cum-secs-per-call stats
 187 @end defun
 188
 189 @anchor{statprof statprof-display}@defun statprof-display . _
 190 Displays a gprof-like summary of the statistics collected. Unless an
 191 optional @var{port} argument is passed, uses the current output port.
 192
 193 @end defun
 194
 195 @anchor{statprof statprof-display-anomolies}@defun statprof-display-anomolies
 196 A sanity check that attempts to detect anomolies in statprof's
 197 statistics.@code{}
 198
 199 @end defun
 200
 201 @anchor{statprof statprof-fetch-stacks}@defun statprof-fetch-stacks
 202 Returns a list of stacks, as they were captured since the last call to
 203 @code{statprof-reset}.
 204
 205 Note that stacks are only collected if the @var{full-stacks?} argument
 206 to @code{statprof-reset} is true.
 207
 208 @end defun
 209
 210 @anchor{statprof statprof-fetch-call-tree}@defun statprof-fetch-call-tree
 211 @verbatim
 212 Return a call tree for the previous statprof run.
 213
 214 The return value is a list of nodes, each of which is of the type:
 215 @@code
 216  node ::= (@@var@{proc@} @@var@{count@} . @@var@{nodes@})
 217 @@end code
 218 @end verbatim
 219
 220 @end defun
 221
 222 @anchor{statprof statprof}@defun statprof thunk [#:loop] [#:hz] [#:count-calls?] [#:full-stacks?]
 223 Profile the execution of @var{thunk}, and return its return values.
 224
 225 The stack will be sampled @var{hz} times per second, and the thunk
 226 itself will be called @var{loop} times.
 227
 228 If @var{count-calls?} is true, all procedure calls will be recorded.
 229 This operation is somewhat expensive.
 230
 231 If @var{full-stacks?} is true, at each sample, statprof will store away
 232 the whole call tree, for later analysis. Use
 233 @code{statprof-fetch-stacks} or @code{statprof-fetch-call-tree} to
 234 retrieve the last-stored stacks.
 235
 236 @end defun
 237
 238 @anchor{statprof with-statprof}@defspec with-statprof args
 239 Profile the expressions in the body, and return the body's return
 240 value.
 241
 242 Keyword arguments:
 243
 244 @table @code
 245 @item #:loop
 246 Execute the body @var{loop} number of times, or @code{#f} for no looping
 247
 248 default: @code{#f}
 249
 250 @item #:hz
 251 Sampling rate
 252
 253 default: @code{20}
 254
 255 @item #:count-calls?
 256 Whether to instrument each function call (expensive)
 257
 258 default: @code{#f}
 259
 260 @item #:full-stacks?
 261 Whether to collect away all sampled stacks into a list
 262
 263 default: @code{#f}
 264
 265 @end table
 266
 267 @end defspec
 268
 269 @anchor{statprof gcprof}@defun gcprof thunk [#:loop] [#:full-stacks?]
 270 Do an allocation profile of the execution of @var{thunk}.
 271
 272 The stack will be sampled soon after every garbage collection, yielding
 273 an approximate idea of what is causing allocation in your program.
 274
 275 Since GC does not occur very frequently, you may need to use the
 276 @var{loop} parameter, to cause @var{thunk} to be called @var{loop}
 277 times.
 278
 279 If @var{full-stacks?} is true, at each sample, statprof will store away
 280 the whole call tree, for later analysis. Use
 281 @code{statprof-fetch-stacks} or @code{statprof-fetch-call-tree} to
 282 retrieve the last-stored stacks.
 283
 284 @end defun