Next: , Up: Standard Library


8.1 (statprof)

8.1.1 Overview

(statprof) is intended to be a fairly simple statistical profiler for guile. It is in the early stages yet, so consider its output still suspect, and please report any bugs to guile-devel at gnu.org, or to me directly at rlb at defaultvalue.org.

A simple use of statprof would look like this:

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

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:

       %   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
      ...

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.

% time
The percent of the time spent inside the procedure itself (not counting children).
cumulative seconds
The total number of seconds spent in the procedure, including children.
self seconds
The total number of seconds spent in the procedure itself (not counting children).
calls
The total number of times the procedure was called.
self ms/call
The average time taken by the procedure itself on each call, in ms.
total ms/call
The average time taken by each call to the procedure, including time spent in child functions.
name
The name of the procedure.

The profiler uses 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 :-)

8.1.2 Implementation notes

The profiler works by setting the unix profiling signal ITIMER_PROF to go off after the interval you define in the call to 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 get-internal-run-time, how much CPU time (system and user – which is also what 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.

8.1.3 Usage

— Function: statprof-active?

Returns #t if statprof-start has been called more times than statprof-stop, #f otherwise.

— Function: statprof-start

Start the profiler.

— Function: statprof-stop

Stop the profiler.

— Function: statprof-reset sample-seconds sample-microseconds count-calls? [full-stacks?]

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

Enables traps and debugging as necessary.

— Function: statprof-accumulated-time

Returns the time accumulated during the last statprof run.

— Function: statprof-sample-count

Returns the number of samples taken during the last statprof run.

— Function: statprof-fold-call-data proc init

Fold proc over the call-data accumulated by statprof. Cannot be called while statprof is active. proc should take two arguments, (call-data prior-result).

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

— Function: statprof-proc-call-data proc

Returns the call-data associated with proc, or #f if none is available.

— Function: statprof-call-data-name cd

— Function: statprof-call-data-calls cd

— Function: statprof-call-data-cum-samples cd

— Function: statprof-call-data-self-samples cd

— Function: statprof-call-data->stats call-data

Returns an object of type statprof-stats.

— Function: statprof-stats-proc-name stats

— Function: statprof-stats-%-time-in-proc stats

— Function: statprof-stats-cum-secs-in-proc stats

— Function: statprof-stats-self-secs-in-proc stats

— Function: statprof-stats-calls stats

— Function: statprof-stats-self-secs-per-call stats

— Function: statprof-stats-cum-secs-per-call stats

— Function: statprof-display . _

Displays a gprof-like summary of the statistics collected. Unless an optional port argument is passed, uses the current output port.

— Function: statprof-display-anomolies

A sanity check that attempts to detect anomolies in statprof's statistics.

— Function: statprof-fetch-stacks

Returns a list of stacks, as they were captured since the last call to statprof-reset.

Note that stacks are only collected if the full-stacks? argument to statprof-reset is true.

— Function: statprof-fetch-call-tree
     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

— Function: statprof thunk [#:loop] [#:hz] [#:count-calls?] [#:full-stacks?]

Profiles the execution of thunk.

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

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

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

— Special Form: with-statprof args

Profiles the expressions in its body.

Keyword arguments:

#:loop
Execute the body loop number of times, or #f for no looping

default: #f

#:hz
Sampling rate

default: 20

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

default: #f

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

default: #f

— Function: gcprof thunk [#:loop] [#:full-stacks?]

Do an allocation profile of the execution of 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 loop parameter, to cause thunk to be called loop times.

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