[Guile-commits] 09/10: Update statprof documentation; deprecate `with-statprof'

[Andy Wingo]

wingo pushed a commit to branch master
in repository guile.

commit 8998f1539f9b998a9ec5f867d3933cdd8f06fc41
Author: Andy Wingo <address@hidden>
Date:   Mon Feb 1 14:58:34 2016 +0100

    Update statprof documentation; deprecate `with-statprof'
    
    * module/statprof.scm: Remove most of the commentary, as it was
      duplicated in the manual and was getting out of date.
      (stats): Remove self-secs-per-call and cum-secs-per-call fields as
      they can be computed from the other fields.
      (statprof-call-data->stats): Adapt.
      (statprof-stats-self-secs-per-call):
      (statprof-stats-cum-secs-per-call): New functions.
      (statprof-display/flat): Don't print the seconds-per-call fields, as
      we are no longer stopping the clock around call counters.  Anyway
      these times were quite misleading.
      (with-statprof): Deprecate.  It took its keyword arguments at the
      beginning; very complicated!  Better to use the `statprof' function.
      (`statprof' was introduced after `with-statprof' and then
      `with-statprof' was adapted to use it.)
    
    * doc/ref/statprof.texi (Statprof): Port this documentation away from
      the automatically generated text and update it for the new interfaces
      like #:display-style.
    
    * module/system/base/syntax.scm (record-case): Remove comment that
      referenced with-statprof.  Add comment indicating that record-case
      should be replaced.
    
    * doc/ref/scheme-using.texi (Profile Commands): Update to mention
      keyword arguments and to link to the statprof documentation.
---
 doc/ref/scheme-using.texi     |    8 +-
 doc/ref/statprof.texi         |  414 +++++++++++++++++++----------------------
 module/statprof.scm           |  161 +++++-----------
 module/system/base/syntax.scm |   30 +---
 4 files changed, 244 insertions(+), 369 deletions(-)

diff --git a/doc/ref/scheme-using.texi b/doc/ref/scheme-using.texi
index 9334218..b7efcb4 100644
--- a/doc/ref/scheme-using.texi
+++ b/doc/ref/scheme-using.texi
@@ -294,8 +294,12 @@ Disassemble a file.
 Time execution.
 @end deffn
 
address@hidden {REPL Command} profile exp
-Profile execution.
address@hidden {REPL Command} profile exp [#:hz hz=100] @
+  [#:count-calls? count-calls?=#f] [#:display-style display-style=list]
+Profile execution of an expression.  This command compiled @var{exp} and
+then runs it within the statprof profiler, passing all keyword options
+to the @code{statprof} procedure.  For more on statprof and on the the
+options available to this command, @xref{Statprof}.
 @end deffn
 
 @deffn {REPL Command} trace exp [#:width w] [#:max-indent i]
diff --git a/doc/ref/statprof.texi b/doc/ref/statprof.texi
index 5b99fb6..6282811 100644
--- a/doc/ref/statprof.texi
+++ b/doc/ref/statprof.texi
@@ -6,279 +6,245 @@
 @node Statprof
 @section Statprof
 
address@hidden(statprof)} is a fairly simple statistical profiler for Guile.
+Statprof is a statistical profiler for Guile.
 
 A simple use of statprof would look like this:
 
address@hidden 
-(statprof-reset 0 50000 #t)
-(statprof-start)
-(do-something)
-(statprof-stop)
-(statprof-display)
address@hidden
+(use-modules (statprof))
+(statprof (lambda ()
+            (map 1+ (iota 1000000))
+            #f))
 @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:
-
address@hidden 
-  %   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
- ...
+This would run the thunk with statistical profiling, finally displaying
+a flat table of statistics which could look something like this:
+
address@hidden
+%     cumulative   self
+time   seconds     seconds  procedure
+ 57.14  39769.73      0.07  ice-9/boot-9.scm:249:5:map1
+ 28.57      0.04      0.04  ice-9/boot-9.scm:1165:0:iota
+ 14.29      0.02      0.02  1+
+  0.00      0.12      0.00  <current input>:2:10
+---
+Sample count: 7
+Total time: 0.123490713 seconds (0.201983993 seconds in GC)
 @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.
-
address@hidden @asis
address@hidden % time
-The percent of the time spent inside the procedure itself (not counting
-children).
-
address@hidden cumulative seconds
-The total number of seconds spent in the procedure, including children.
-
address@hidden self seconds
-The total number of seconds spent in the procedure itself (not counting
-children).
-
address@hidden calls
-The total number of times the procedure was called.
-
address@hidden self ms/call
-The average time taken by the procedure itself on each call, in ms.
-
address@hidden total ms/call
-The average time taken by each call to the procedure, including time
-spent in child functions.
-
address@hidden name
-The name of the procedure.
-
address@hidden table
+all of statprof, ``time'' refers to execution time (both user and
+system), not wall clock time.
+
+The @code{% time} column indicates the percentage of the run-time time
+spent inside the procedure itself (not counting children).  It is
+calculated as @code{self seconds}, measuring the amount of time spent in
+the procedure, divided by the total run-time.
+
address@hidden seconds} also counts time spent in children of a
+function.  For recursive functions, this can exceed the total time, as
+in our example above, because each activation on the stack adds to the
+cumulative time.
+
+Finally, the GC time measures the time spent in the garbage collector.
+On systems with multiple cores, this time can be larger than the run
+time, because it counts time spent in all threads, and will run the
+``marking'' phase of GC in parallel.  If GC time is a significant
+fraction of the run time, that means that most time in your program is
+spent allocating objects and cleaning up after those allocations.  To
+speed up your program, one good place to start would be to look at how
+to reduce the allocation rate.
+
+Statprof's main mode of operation is as a statistical profiler.  However
+statprof can also run in a ``precise'' mode as well.  Pass the
address@hidden:count-calls? #t} keyword argument to @code{statprof} to record
+all calls:
+
address@hidden
+(use-modules (statprof))
+(statprof (lambda ()
+            (map 1+ (iota 1000000))
+            #f)
+          #:count-calls? #t)
address@hidden example
 
-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.
+The result has an additional @code{calls} column:
+
address@hidden
+%     cumulative   self             
+time   seconds    seconds   calls   procedure
+ 82.26      0.73      0.73 1000000  1+
+ 11.29 420925.80      0.10 1000001  ice-9/boot-9.scm:249:5:map1
+  4.84      0.06      0.04       1  ice-9/boot-9.scm:1165:0:iota
+[...]
+---
+Sample count: 62
+Total time: 0.893098065 seconds (1.222796536 seconds in GC)
address@hidden example
 
-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 :-)
+As you can see, the profile is perturbed: @code{1+} ends up on top,
+whereas it was not marked as hot in the earlier profile.  This is
+because the overhead of call-counting unfairly penalizes calls.  Still,
+this precise mode can be useful at times to do algorithmic optimizations
+based on the precise call counts.
 
 @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
address@hidden 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.
+to @code{statprof-reset}.  When the signal fires, a sampling routine
+runs which crawls up the stack, recording all instruction pointers into
+a buffer.  After the sample is complete, the profiler resets profiling
+timer to fire again after the appropriate interval.
+
+Later, when profiling stops, that log buffer is analyzed to produce the
+``self seconds'' and ``cumulative seconds'' statistics.  A procedure at
+the top of the stack counts toward ``self'' samples, and everything on
+the stack counts towards ``cumulative'' samples.
+
+While the profiler is running it measures how much CPU time (system and
+user -- which is also what @code{ITIMER_PROF} tracks) has elapsed while
+code has been executing within the profiler.  Only run time counts
+towards the profile, not wall-clock time.  For example, sleeping and
+waiting for input or output do not cause the timer clock to advance.
 
 @section Usage
address@hidden address@hidden statprof-active? 
-Returns @code{#t} if @code{statprof-start} has been called more times
-than @code{statprof-stop}, @code{#f} otherwise.
 
address@hidden defun
-
address@hidden address@hidden statprof-start 
-Start the address@hidden
-
address@hidden defun
address@hidden {Scheme Procedure} statprof thunk @
+       [#:loop loop=1] [#:hz hz=100] @
+       [#:port port=(current-output-port)] @
+       [#:count-calls? count-calls?=#f] @
+       [#:display-style display-style='flat]
+Profile the execution of @var{thunk}, and return its return values.
 
address@hidden address@hidden statprof-stop 
-Stop the address@hidden
+The stack will be sampled @var{hz} times per second, and the thunk
+itself will be called @var{loop} times.
 
address@hidden defun
+If @var{count-calls?} is true, all procedure calls will be recorded.
+This operation is somewhat expensive.
 
address@hidden address@hidden statprof-reset sample-seconds sample-microseconds 
count-calls? [full-stacks?]
-Reset the statprof sampler interval to @var{sample-seconds} and
address@hidden 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.
+After the @var{thunk} has been profiled, print out a profile to
address@hidden  If @var{display-style} is @code{flat}, the results will be
+printed as a flat profile.  Otherwise if @var{display-style} is
address@hidden, print the results as a tree profile.
address@hidden deffn
 
-Enables traps and debugging as necessary.
+Profiling can also be enabled and disabled manually.
 
address@hidden defun
address@hidden {Scheme Procedure} statprof-active? 
+Returns @code{#t} if @code{statprof-start} has been called more times
+than @code{statprof-stop}, @code{#f} otherwise.
address@hidden deffn
 
address@hidden address@hidden statprof-accumulated-time 
-Returns the time accumulated during the last statprof address@hidden
address@hidden {Scheme Procedure} statprof-start 
address@hidden {Scheme Procedure} statprof-stop 
+Start or stop the profiler.
address@hidden deffn
 
address@hidden defun
address@hidden {Scheme Procedure} statprof-reset sample-seconds 
sample-microseconds count-calls?
+Reset the profiling sample interval to @var{sample-seconds} and
address@hidden  If @var{count-calls?} is true, arrange to
+instrument procedure calls as well as collecting statistical profiling
+data.
address@hidden deffn
 
address@hidden address@hidden statprof-sample-count 
-Returns the number of samples taken during the last statprof address@hidden
+If you use the manual @code{statprof-start}/@code{statprof-stop}
+interface, an implicit statprof state will persist starting from the
+last call to @code{statprof-reset}, or the first call to
address@hidden  There are a number of accessors to fetch
+statistics from this implicit state.
 
address@hidden defun
address@hidden {Scheme Procedure} statprof-accumulated-time 
+Returns the time accumulated during the last statprof run.
address@hidden deffn
 
address@hidden address@hidden 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,
address@hidden(@var{call-data} @var{prior-result})}.
address@hidden {Scheme Procedure} statprof-sample-count 
+Returns the number of samples taken during the last statprof run.
address@hidden deffn
 
-Note that a given proc-name may appear multiple times, but if it does,
-it represents different functions with the same name.
address@hidden {Scheme Procedure} statprof-fold-call-data proc init
+Fold @var{proc} over the call-data accumulated by statprof.  This
+procedure cannot be called while statprof is active.
 
address@hidden defun
address@hidden will be called with arguments, @var{call-data} and
address@hidden
address@hidden deffn
 
address@hidden address@hidden statprof-proc-call-data proc
address@hidden {Scheme Procedure} statprof-proc-call-data proc
 Returns the call-data associated with @var{proc}, or @code{#f} if none
 is available.
address@hidden deffn
 
address@hidden defun
-
address@hidden address@hidden statprof-call-data-name cd
address@hidden defun
-
address@hidden address@hidden statprof-call-data-calls cd
address@hidden defun
address@hidden {Scheme Procedure} statprof-call-data-name cd
address@hidden {Scheme Procedure} statprof-call-data-calls cd
address@hidden {Scheme Procedure} statprof-call-data-cum-samples cd
address@hidden {Scheme Procedure} statprof-call-data-self-samples cd
+Accessors for the fields in a statprof call-data object.
address@hidden deffn
 
address@hidden address@hidden statprof-call-data-cum-samples cd
address@hidden defun
-
address@hidden address@hidden statprof-call-data-self-samples cd
address@hidden defun
-
address@hidden statprof-call-data->address@hidden statprof-call-data->stats 
call-data
address@hidden {Scheme Procedure} statprof-call-data->stats call-data
 Returns an object of type @code{statprof-stats}.
address@hidden deffn
+
address@hidden {Scheme Procedure} statprof-stats-proc-name stats
address@hidden {Scheme Procedure} statprof-stats-%-time-in-proc stats
address@hidden {Scheme Procedure} statprof-stats-cum-secs-in-proc stats
address@hidden {Scheme Procedure} statprof-stats-self-secs-in-proc stats
address@hidden {Scheme Procedure} statprof-stats-calls stats
address@hidden {Scheme Procedure} statprof-stats-self-secs-per-call stats
address@hidden {Scheme Procedure} statprof-stats-cum-secs-per-call stats
+Accessors for the fields in a @code{statprof-stats} object.
address@hidden deffn
+
address@hidden {Scheme Procedure} statprof-display @
+       [port=(current-output-port)] [#:style style=flat]
+Displays a summary of the statistics collected.  Possible values for
address@hidden include:
 
address@hidden defun
-
address@hidden address@hidden statprof-stats-proc-name stats
address@hidden defun
-
address@hidden address@hidden statprof-stats-%-time-in-proc stats
address@hidden defun
-
address@hidden address@hidden statprof-stats-cum-secs-in-proc stats
address@hidden defun
-
address@hidden address@hidden statprof-stats-self-secs-in-proc stats
address@hidden defun
-
address@hidden address@hidden statprof-stats-calls stats
address@hidden defun
-
address@hidden address@hidden statprof-stats-self-secs-per-call stats
address@hidden defun
-
address@hidden address@hidden statprof-stats-cum-secs-per-call stats
address@hidden defun
-
address@hidden address@hidden statprof-display . _
-Displays a gprof-like summary of the statistics collected. Unless an
-optional @var{port} argument is passed, uses the current output port.
-
address@hidden defun
-
address@hidden address@hidden statprof-display-anomolies 
-A sanity check that attempts to detect anomolies in statprof's
address@hidden
-
address@hidden defun
address@hidden @code
address@hidden flat
+Display a traditional gprof-style flat profile.
address@hidden anomalies
+Find statistical anomalies in the data.
address@hidden tree
+Display a tree profile.
address@hidden table
address@hidden deffn
 
address@hidden address@hidden statprof-fetch-stacks 
address@hidden {Scheme Procedure} statprof-fetch-stacks 
 Returns a list of stacks, as they were captured since the last call to
 @code{statprof-reset}.
address@hidden deffn
 
-Note that stacks are only collected if the @var{full-stacks?} argument
-to @code{statprof-reset} is true.
-
address@hidden defun
-
address@hidden address@hidden statprof-fetch-call-tree 
address@hidden {Scheme Procedure} statprof-fetch-call-tree [#:precise 
precise?=#f]
 @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 ::= (@@address@hidden@} @@address@hidden@} . @@address@hidden@})
-@@end code
+The return value is a list of nodes.  A node is a list of the form:
address@hidden
+ node ::= (@var{proc} @var{count} . @var{nodes})
address@hidden code
+
+The @var{proc} is a printable representation of a procedure, as a
+string.  If @var{precise?} is false, which is the default, then a node
+corresponds to a procedure invocation.  If it is true, then a node
+corresponds to a return point in a procedure.  Passing @code{#:precise?
+#t} allows a user to distinguish different source lines in a procedure,
+but usually it is too much detail, so it is off by default.
 @end verbatim
 
address@hidden defun
-
address@hidden address@hidden statprof thunk [#:loop] [#:hz] [#:count-calls?] 
[#:full-stacks?]
-Profile the execution of @var{thunk}, and return its return values.
-
-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
address@hidden or @code{statprof-fetch-call-tree} to
-retrieve the last-stored stacks.
address@hidden deffn
 
address@hidden defun
address@hidden {Scheme Procedure} gcprof thunk [#:loop]
+Like the @code{statprof} procedure, but instead of profiling CPU time,
+we profile garbage collection.
 
address@hidden address@hidden with-statprof args
-Profile the expressions in the body, and return the body's return
-value.
-
-Keyword arguments:
-
address@hidden @code
address@hidden #:loop
-Execute the body @var{loop} number of times, or @code{#f} for no looping
-
-default: @code{#f}
-
address@hidden #:hz
-Sampling rate
-
-default: @code{20}
-
address@hidden #:count-calls?
-Whether to instrument each function call (expensive)
-
-default: @code{#f}
-
address@hidden #:full-stacks?
-Whether to collect away all sampled stacks into a list
-
-default: @code{#f}
-
address@hidden table
-
address@hidden defspec
-
address@hidden address@hidden 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.
+The stack will be sampled soon after every garbage collection during the
+evaluation of @var{thunk}, 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
address@hidden or @code{statprof-fetch-call-tree} to
-retrieve the last-stored stacks.
-
address@hidden defun
address@hidden deffn
diff --git a/module/statprof.scm b/module/statprof.scm
index 3c7c3f7..03178da 100644
--- a/module/statprof.scm
+++ b/module/statprof.scm
@@ -1,7 +1,7 @@
 ;;;; (statprof) -- a statistical profiler for Guile
 ;;;; -*-scheme-*-
 ;;;;
-;;;;   Copyright (C) 2009, 2010, 2011, 2013-2015  Free Software Foundation, 
Inc.
+;;;;   Copyright (C) 2009, 2010, 2011, 2013-2016  Free Software Foundation, 
Inc.
 ;;;;    Copyright (C) 2004, 2009 Andy Wingo <wingo at pobox dot com>
 ;;;;    Copyright (C) 2001 Rob Browning <rlb at defaultvalue dot org>
 ;;;; 
@@ -23,77 +23,8 @@
 
 ;;; Commentary:
 ;;;
-;;; @code{(statprof)} is a statistical profiler for Guile.
-;;;
-;;; A simple use of statprof would look like this:
-;;;
-;;; @example
-;;;   (statprof (lambda () (do-something))
-;;;             #:hz 100
-;;;             #:count-calls? #t)
-;;; @end example
-;;;
-;;; This would run the thunk with statistical profiling, finally
-;;; displaying a gprof flat-style table of statistics which could
-;;; 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
-;;;
-;;; @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.
+;;; @code{(statprof)} is a statistical profiler for Guile.  See the
+;;; "Statprof" section in the manual, for more information.
 ;;;
 ;;; Code:
 
@@ -140,8 +71,6 @@
             statprof-fetch-call-tree
 
             statprof
-            with-statprof
-
             gcprof))
 
 
@@ -612,16 +541,28 @@ none is available."
 (define-record-type stats
   (make-stats proc-name proc-source
               %-time-in-proc cum-secs-in-proc self-secs-in-proc
-              calls self-secs-per-call cum-secs-per-call)
+              calls)
   stats?
   (proc-name statprof-stats-proc-name)
   (proc-source statprof-stats-proc-source)
   (%-time-in-proc statprof-stats-%-time-in-proc)
   (cum-secs-in-proc statprof-stats-cum-secs-in-proc)
   (self-secs-in-proc statprof-stats-self-secs-in-proc)
-  (calls statprof-stats-calls)
-  (self-secs-per-call statprof-stats-self-secs-per-call)
-  (cum-secs-per-call statprof-stats-cum-secs-per-call))
+  (calls statprof-stats-calls))
+
+(define (statprof-stats-self-secs-per-call stats)
+  (let ((calls (statprof-stats-calls stats)))
+    (and calls
+         (/ (statprof-stats-self-secs-in-proc stats)
+            calls))))
+
+(define (statprof-stats-cum-secs-per-call stats)
+  (let ((calls (statprof-stats-calls stats)))
+    (and calls
+         (/ (statprof-stats-cum-secs-in-proc stats)
+            ;; `calls' might be 0 if we entered statprof during the
+            ;; dynamic extent of the call.
+            (max calls 1)))))
 
 (define (statprof-call-data->stats call-data)
   "Returns an object of type @code{statprof-stats}."
@@ -645,16 +586,7 @@ none is available."
                 (* (/ self-samples all-samples) 100.0)
                 (* cum-samples secs-per-sample 1.0)
                 (* self-samples secs-per-sample 1.0)
-                num-calls
-                (and num-calls ;; maybe we only sampled in children
-                     (if (zero? self-samples) 0.0
-                         (/ (* self-samples secs-per-sample) 1.0 num-calls)))
-                (and num-calls ;; cum-samples must be positive
-                     (/ (* cum-samples secs-per-sample)
-                        1.0
-                        ;; num-calls might be 0 if we entered statprof during 
the
-                        ;; dynamic extent of the call
-                        (max num-calls 1))))))
+                num-calls)))
 
 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
 
@@ -689,10 +621,8 @@ optional @var{port} argument is passed, uses the current 
output port."
                 (statprof-stats-self-secs-in-proc stats))
         (if (call-counts state)
             (if (statprof-stats-calls stats)
-                (format port " ~7d ~8,2f ~8,2f  "
-                        (statprof-stats-calls stats)
-                        (* 1000 (statprof-stats-self-secs-per-call stats))
-                        (* 1000 (statprof-stats-cum-secs-per-call stats)))
+                (format port " ~7d  "
+                        (statprof-stats-calls stats))
                 (format port "                            "))
             (display "  " port))
         (let ((source (statprof-stats-proc-source stats))
@@ -707,10 +637,10 @@ optional @var{port} argument is passed, uses the current 
output port."
     
       (if (call-counts state)
           (begin
-            (format  port "~5a ~10a   ~7a ~8a ~8a ~8a  address@hidden"
-                     "%  " "cumulative" "self" "" "self" "total" "")
-            (format  port "~5a  ~9a  ~8a ~8a ~8a ~8a  ~a\n"
-                     "time" "seconds" "seconds" "calls" "ms/call" "ms/call" 
"procedure"))
+            (format  port "~5a ~10a   ~7a  ~8a\n"
+                     "%  " "cumulative" "self" "")
+            (format  port "~5a  ~9a  ~8a  ~7a ~a\n"
+                     "time" "seconds" "seconds" "calls" "procedure"))
           (begin
             (format  port "~5a ~10a   ~7a  ~8a\n"
                      "%" "cumulative" "self" "")
@@ -963,8 +893,9 @@ operation is somewhat expensive."
           (statprof-stop state)
           (statprof-display port state #:style display-style))))))
 
-(define-macro (with-statprof . args)
-  "Profile the expressions in the body, and return the body's return values.
+(begin-deprecated
+ (define-macro (with-statprof . args)
+   "Profile the expressions in the body, and return the body's return values.
 
 Keyword arguments:
 
@@ -982,22 +913,24 @@ Whether to instrument each function call (expensive)
 
 default: @code{#f}
 @end table"
-  (define (kw-arg-ref kw args def)
-    (cond
-     ((null? args) (error "Invalid macro body"))
-     ((keyword? (car args))
-      (if (eq? (car args) kw)
-          (cadr args)
-          (kw-arg-ref kw (cddr args) def)))
-     ((eq? kw #f def) ;; asking for the body
-      args)
-     (else def))) ;; kw not found
-  `((@ (statprof) statprof)
-    (lambda () ,@(kw-arg-ref #f args #f))
-    #:loop ,(kw-arg-ref #:loop args 1)
-    #:hz ,(kw-arg-ref #:hz args 100)
-    #:count-calls? ,(kw-arg-ref #:count-calls? args #f)
-    #:full-stacks? ,(kw-arg-ref #:full-stacks? args #f)))
+   (define (kw-arg-ref kw args def)
+     (cond
+      ((null? args) (error "Invalid macro body"))
+      ((keyword? (car args))
+       (if (eq? (car args) kw)
+           (cadr args)
+           (kw-arg-ref kw (cddr args) def)))
+      ((eq? kw #f def) ;; asking for the body
+       args)
+      (else def))) ;; kw not found
+   (issue-deprecation-warning
+    "`with-statprof' is deprecated.  Use `statprof' instead.")
+   `((@ (statprof) statprof)
+     (lambda () ,@(kw-arg-ref #f args #f))
+     #:loop ,(kw-arg-ref #:loop args 1)
+     #:hz ,(kw-arg-ref #:hz args 100)
+     #:count-calls? ,(kw-arg-ref #:count-calls? args #f)))
+ (export with-statprof))
 
 (define* (gcprof thunk #:key (loop 1) full-stacks? (port 
(current-output-port)))
   "Do an allocation profile of the execution of @var{thunk}.
diff --git a/module/system/base/syntax.scm b/module/system/base/syntax.scm
index 249961d..fafcce4 100644
--- a/module/system/base/syntax.scm
+++ b/module/system/base/syntax.scm
@@ -146,35 +146,7 @@
                    (car in)
                    out)))))))
 
-;; So, dear reader. It is pleasant indeed around this fire or at this
-;; cafe or in this room, is it not? I think so too.
-;;
-;; This macro used to generate code that looked like this:
-;;
-;;  `(((record-predicate ,record-type) ,r)
-;;    (let ,(map (lambda (slot)
-;;                 (if (pair? slot)
-;;                     `(,(car slot) ((record-accessor ,record-type ',(cadr 
slot)) ,r))
-;;                     `(,slot ((record-accessor ,record-type ',slot) ,r))))
-;;               slots)
-;;      ,@body)))))
-;;
-;; But this was a hot spot, so computing all those predicates and
-;; accessors all the time was getting expensive, so we did a terrible
-;; thing: we decided that since above we're already defining accessors
-;; and predicates with computed names, we might as well just rely on that fact 
here.
-;;
-;; It's a bit nasty, I agree. But it is fast.
-;;
-;;scheme@(guile-user)> (with-statprof #:hz 1000 #:full-stacks? #t 
(resolve-module '(oop goops)))%     cumulative   self             
-;; time   seconds     seconds      name
-;;   8.82      0.03      0.01  glil->assembly
-;;   8.82      0.01      0.01  record-type-fields
-;;   5.88      0.01      0.01  %compute-initargs
-;;   5.88      0.01      0.01  list-index
-
-
-;;; So ugly... but I am too ignorant to know how to make it better.
+;;; FIXME: Re-write uses of `record-case' to use `match' instead.
 (define-syntax record-case
   (lambda (x)
     (syntax-case x ()