Customizing Common Lisp's Iterate: Timing
Posted on October 10th, 2016.
This entry is the second in a series about customizing Common Lisp's iterate library. The full series:
This post will show how to make a timing clause that keeps track of how much
time has elapsed between iterations (and across the entire loop). I've found it
handy when doing rough benchmarks for things like maze generation.
End Result
Before we look at the code, let's look at what we're aiming for:
(defun to-seconds (internal-time-units)
(/ internal-time-units internal-time-units-per-second 1.0))
(iterate
(repeat 5)
(sleep (random 3.0))
(timing real-time :since-start-into total-time
:per-iteration-into loop-time)
(collect loop-time :into loop-times)
(finally
(format t "Individual times: ~S~%Total time: ~F seconds~%"
(mapcar #'to-seconds loop-times)
(to-seconds total-time))))
; =>
Individual times: (0.948 1.359 2.828 2.891 2.744)
Total time: 10.77 secondsThe timing clause is what we'll be implementing.
Code
The code for timing is fairly short but does have a few interesting things to
talk about. I've omitted the docstring so it'll fit on one screen:
(defmacro-clause (TIMING time-type &optional
SINCE-START-INTO since-var
PER-ITERATION-INTO per-var)
(let ((timing-function (ecase time-type
((real-time) #'get-internal-real-time)
((run-time) #'get-internal-run-time)))
(since-var (or since-var
(when (null per-var)
iterate::*result-var*))))
(with-gensyms (start-time current-time previous-time)
`(progn
(with ,start-time = (funcall ,timing-function))
(for ,current-time = (funcall ,timing-function))
,@(when since-var
`((for ,since-var = (- ,current-time ,start-time))))
,@(when per-var
`((for ,previous-time :previous ,current-time
:initially ,start-time)
(for ,per-var = (- ,current-time ,previous-time))))))))Times are recorded in "internal time units" to be consistent with other Common Lisp functions like get-internal-real-time. Some implementations will be more precise than others.
Argument Pairing
One thing that I sometimes find annoying about iterate clauses is that they
must contain pairs of arguments. You can't have an odd number of arguments,
like:
(TIMING &optional SINCE-START since-var PER-ITERATION per-var).Often, however, you can make the best of this restriction and come up with
something at least moderately useful to use as an extra argument to pad things
out. For the timing clause I decided to make the second argument define which
type of time to measure (process run time or wall clock time).
Symbols & Keywords
In this implementation the type of time to record is given as a symbol in this
package's namespace. This means that you'll want to export the real-time and
run-time symbols from this package, not just the timing symbol. This is
a little annoying, but I like how it looks when used.
Another option would be to change these to keyword symbols, so you would say
(timing :real-time ...) instead. Or you could just support both (ecase
makes this easy).
Note the use of ecase when checking the time type to signal an error at
macroexpansion time with a helpful message if the user passed something
incorrect:
(iterate (timing foo :since-start-into some-var))
; =>
debugger invoked on a SB-KERNEL:CASE-FAILURE in thread
#<THREAD "main thread" RUNNING {10028F7473}>:
FOO fell through ECASE expression. Wanted one of (REAL-TIME RUN-TIME).
...Variables
To fit with the general pattern of iterate clauses, we try to do something
intelligent with the variables depending on what the user says they want. If
the user doesn't specify any variable names, we return the total loop time as
the result of the loop:
(macroexpand-iterate '(timing real-time))
; =>
(PROGN
(WITH #:START-TIME516 = (FUNCALL #<CLOSURE GET-INTERNAL-REAL-TIME>))
(FOR #:CURRENT-TIME517 = (FUNCALL #<CLOSURE GET-INTERNAL-REAL-TIME>))
(FOR ITERATE::*RESULT-VAR* = (- #:CURRENT-TIME517 #:START-TIME516)))
(iterate (repeat 1) (sleep 2.0) (timing real-time))
; =>
2003There's a bit of inefficiency here, because we're recalculating the time on
every iteration even though we really only need to do it once at the very end.
But I suppose someone could be accessing iterate::*result-var* in their loop
body like any other variable, so this will do the right thing in that case (even
if that case is horrifying).
If the user does specify a variable for either measurement, we assume they know what they're doing and don't touch the loop result variable:
(macroexpand-iterate
'(timing real-time :since-start-into x))
; =>
(PROGN
(WITH #:START-TIME525 = (FUNCALL #<CLOSURE GET-INTERNAL-REAL-TIME>))
(FOR #:CURRENT-TIME526 = (FUNCALL #<CLOSURE GET-INTERNAL-REAL-TIME>))
(FOR X = (- #:CURRENT-TIME526 #:START-TIME525)))
(macroexpand-iterate
'(timing real-time :per-iteration-into x))
; =>
(PROGN
(WITH #:START-TIME528 = (FUNCALL #<CLOSURE GET-INTERNAL-REAL-TIME>))
(FOR #:CURRENT-TIME529 = (FUNCALL #<CLOSURE GET-INTERNAL-REAL-TIME>))
(FOR #:PREVIOUS-TIME530 :PREVIOUS #:CURRENT-TIME529 :INITIALLY
#:START-TIME528)
(FOR X = (- #:CURRENT-TIME529 #:PREVIOUS-TIME530)))Splicing
Another thing to note is the use of ,@ to splice the appropriate clauses into
the final progn:
; ...
,@(when since-var
`((for ,since-var = (- ,current-time ,start-time))))
,@(when per-var
`((for ,previous-time :previous ,current-time
:initially ,start-time)
(for ,per-var = (- ,current-time ,previous-time))))
; ...For the since-var clause we could have gotten away with just using a plain ,
and returning the for clause itself:
; ...
,(when since-var
`(for ,since-var = (- ,current-time ,start-time)))
; ...This would work, but when since-var is null (when the user wants only the
per-iteration time) the when statement would evaluate to nil, and would
leave a stray nil in the progn:
(macroexpand-iterate
'(timing real-time :per-iteration-into x))
; =>
(PROGN
(WITH #:START-TIME531 = (FUNCALL #<CLOSURE GET-INTERNAL-REAL-TIME>))
(FOR #:CURRENT-TIME532 = (FUNCALL #<CLOSURE GET-INTERNAL-REAL-TIME>))
NIL
(FOR #:PREVIOUS-TIME533 :PREVIOUS #:CURRENT-TIME532 :INITIALLY
#:START-TIME531)
(FOR X = (- #:CURRENT-TIME532 #:PREVIOUS-TIME533)))Any decent compiler will optimize this away, but it's ugly to read during macroexpansion. If we're going to write this thing let's do it right and not be lazy.
Also notice that we don't define the previous-time clause at all unless the
user wants per-iteration time, because the since-start time doesn't need it at
all. No reason to waste cycles calculating an extra value on every iteration if
we don't have to.
Composing
One of the great things about iterate is that the extensions you make can use
each other. For example, we can use last post's averaging clause with the one
we just made to calculate the average time per loop iteration:
(iterate
(repeat 20)
(sleep (random 1.0))
(timing real-time :per-iteration-into time)
(averaging (to-seconds time)))
; =>
0.51555