guile/doc/ref/statprof.texi

@c -*-texinfo-*-
@c This is part of the GNU Guile Reference Manual.
@c Copyright (C) 2013 Free Software Foundation, Inc.
@c See the file guile.texi for copying conditions.

@node Statprof
@section Statprof

@code{(statprof)} is a fairly simple statistical profiler for Guile.

A simple use of statprof would look like this:

@example 
(statprof-reset 0 50000 #t)
(statprof-start)
(do-something)
(statprof-stop)
(statprof-display)
@end example

This would reset statprof, clearing all accumulated statistics, then
start profiling, run some code, stop profiling, and finally display a
gprof flat-style table of statistics which will look something like
this:

@example 
  %   cumulative      self              self    total
 time    seconds   seconds    calls  ms/call  ms/call  name
 35.29      0.23      0.23     2002     0.11     0.11  -
 23.53      0.15      0.15     2001     0.08     0.08  positive?
 23.53      0.15      0.15     2000     0.08     0.08  +
 11.76      0.23      0.08     2000     0.04     0.11  do-nothing
  5.88      0.64      0.04     2001     0.02     0.32  loop
  0.00      0.15      0.00        1     0.00   150.59  do-something
 ...
@end example

All of the numerical data with the exception of the calls column is
statistically approximate. In the following column descriptions, and in
all of statprof, "time" refers to execution time (both user and system),
not wall clock time.

@table @asis
@item % time
The percent of the time spent inside the procedure itself (not counting
children).

@item cumulative seconds
The total number of seconds spent in the procedure, including children.

@item self seconds
The total number of seconds spent in the procedure itself (not counting
children).

@item calls
The total number of times the procedure was called.

@item self ms/call
The average time taken by the procedure itself on each call, in ms.

@item total ms/call
The average time taken by each call to the procedure, including time
spent in child functions.

@item name
The name of the procedure.

@end table

The profiler uses @code{eq?} and the procedure object itself to identify
the procedures, so it won't confuse different procedures with the same
name. They will show up as two different rows in the output.

Right now the profiler is quite simplistic. I cannot provide call-graphs
or other higher level information. What you see in the table is pretty
much all there is. Patches are welcome :-)

@section Implementation notes
The profiler works by setting the unix profiling signal
@code{ITIMER_PROF} to go off after the interval you define in the call
to @code{statprof-reset}. When the signal fires, a sampling routine is
run which looks at the current procedure that's executing, and then
crawls up the stack, and for each procedure encountered, increments that
procedure's sample count. Note that if a procedure is encountered
multiple times on a given stack, it is only counted once. After the
sampling is complete, the profiler resets profiling timer to fire again
after the appropriate interval.

Meanwhile, the profiler keeps track, via @code{get-internal-run-time},
how much CPU time (system and user -- which is also what
@code{ITIMER_PROF} tracks), has elapsed while code has been executing
within a statprof-start/stop block.

The profiler also tries to avoid counting or timing its own code as much
as possible.

@section Usage
@anchor{statprof statprof-active?}@defun statprof-active? 
Returns @code{#t} if @code{statprof-start} has been called more times
than @code{statprof-stop}, @code{#f} otherwise.

@end defun

@anchor{statprof statprof-start}@defun statprof-start 
Start the profiler.@code{}

@end defun

@anchor{statprof statprof-stop}@defun statprof-stop 
Stop the profiler.@code{}

@end defun

@anchor{statprof statprof-reset}@defun statprof-reset sample-seconds sample-microseconds count-calls? [full-stacks?]
Reset the statprof sampler interval to @var{sample-seconds} and
@var{sample-microseconds}. If @var{count-calls?} is true, arrange to
instrument procedure calls as well as collecting statistical profiling
data. If @var{full-stacks?} is true, collect all sampled stacks into a
list for later analysis.

Enables traps and debugging as necessary.

@end defun

@anchor{statprof statprof-accumulated-time}@defun statprof-accumulated-time 
Returns the time accumulated during the last statprof run.@code{}

@end defun

@anchor{statprof statprof-sample-count}@defun statprof-sample-count 
Returns the number of samples taken during the last statprof run.@code{}

@end defun

@anchor{statprof statprof-fold-call-data}@defun statprof-fold-call-data proc init
Fold @var{proc} over the call-data accumulated by statprof. Cannot be
called while statprof is active. @var{proc} should take two arguments,
@code{(@var{call-data} @var{prior-result})}.

Note that a given proc-name may appear multiple times, but if it does,
it represents different functions with the same name.

@end defun

@anchor{statprof statprof-proc-call-data}@defun statprof-proc-call-data proc
Returns the call-data associated with @var{proc}, or @code{#f} if none
is available.

@end defun

@anchor{statprof statprof-call-data-name}@defun statprof-call-data-name cd
@end defun

@anchor{statprof statprof-call-data-calls}@defun statprof-call-data-calls cd
@end defun

@anchor{statprof statprof-call-data-cum-samples}@defun statprof-call-data-cum-samples cd
@end defun

@anchor{statprof statprof-call-data-self-samples}@defun statprof-call-data-self-samples cd
@end defun

@anchor{statprof statprof-call-data->stats}@defun statprof-call-data->stats call-data
Returns an object of type @code{statprof-stats}.

@end defun

@anchor{statprof statprof-stats-proc-name}@defun statprof-stats-proc-name stats
@end defun

@anchor{statprof statprof-stats-%-time-in-proc}@defun statprof-stats-%-time-in-proc stats
@end defun

@anchor{statprof statprof-stats-cum-secs-in-proc}@defun statprof-stats-cum-secs-in-proc stats
@end defun

@anchor{statprof statprof-stats-self-secs-in-proc}@defun statprof-stats-self-secs-in-proc stats
@end defun

@anchor{statprof statprof-stats-calls}@defun statprof-stats-calls stats
@end defun

@anchor{statprof statprof-stats-self-secs-per-call}@defun statprof-stats-self-secs-per-call stats
@end defun

@anchor{statprof statprof-stats-cum-secs-per-call}@defun statprof-stats-cum-secs-per-call stats
@end defun

@anchor{statprof statprof-display}@defun statprof-display . _
Displays a gprof-like summary of the statistics collected. Unless an
optional @var{port} argument is passed, uses the current output port.

@end defun

@anchor{statprof statprof-display-anomolies}@defun statprof-display-anomolies 
A sanity check that attempts to detect anomolies in statprof's
statistics.@code{}

@end defun

@anchor{statprof statprof-fetch-stacks}@defun statprof-fetch-stacks 
Returns a list of stacks, as they were captured since the last call to
@code{statprof-reset}.

Note that stacks are only collected if the @var{full-stacks?} argument
to @code{statprof-reset} is true.

@end defun

@anchor{statprof statprof-fetch-call-tree}@defun statprof-fetch-call-tree 
@verbatim 
Return a call tree for the previous statprof run.

The return value is a list of nodes, each of which is of the type:
@@code
 node ::= (@@var@{proc@} @@var@{count@} . @@var@{nodes@})
@@end code
@end verbatim

@end defun

@anchor{statprof statprof}@defun statprof thunk [#:loop] [#:hz] [#:count-calls?] [#:full-stacks?]
Profiles the execution of @var{thunk}.

The stack will be sampled @var{hz} times per second, and the thunk
itself will be called @var{loop} times.

If @var{count-calls?} is true, all procedure calls will be recorded.
This operation is somewhat expensive.

If @var{full-stacks?} is true, at each sample, statprof will store away
the whole call tree, for later analysis. Use
@code{statprof-fetch-stacks} or @code{statprof-fetch-call-tree} to
retrieve the last-stored stacks.

@end defun

@anchor{statprof with-statprof}@defspec with-statprof args
Profiles the expressions in its body.

Keyword arguments:

@table @code
@item #:loop
Execute the body @var{loop} number of times, or @code{#f} for no looping

default: @code{#f}

@item #:hz
Sampling rate

default: @code{20}

@item #:count-calls?
Whether to instrument each function call (expensive)

default: @code{#f}

@item #:full-stacks?
Whether to collect away all sampled stacks into a list

default: @code{#f}

@end table

@end defspec

@anchor{statprof gcprof}@defun gcprof thunk [#:loop] [#:full-stacks?]
Do an allocation profile of the execution of @var{thunk}.

The stack will be sampled soon after every garbage collection, yielding
an approximate idea of what is causing allocation in your program.

Since GC does not occur very frequently, you may need to use the
@var{loop} parameter, to cause @var{thunk} to be called @var{loop}
times.

If @var{full-stacks?} is true, at each sample, statprof will store away
the whole call tree, for later analysis. Use
@code{statprof-fetch-stacks} or @code{statprof-fetch-call-tree} to
retrieve the last-stored stacks.

@end defun