content/blog/2016/10/iterate-timing.markdown @ 3bd8a34568c3

(
:title "Customizing Common Lisp's Iterate: Timing"
:snip "How long is this loop?"
:date "2016-10-10T14:50:00Z"
:draft nil

)

This entry is the second in a series about customizing Common Lisp's [iterate][]
library.  The full series:

* [Averaging](/blog/2016/09/iterate-averaging/)
* [Timing](/blog/2016/10/iterate-timing/)

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][mazes].

[mazes]: http://www.amazon.com/dp/1680500554/?tag=stelos-20
[iterate]: https://common-lisp.net/project/iterate/

<div id="toc"></div>

## End Result

Before we look at the code, let's look at what we're aiming for:

```lisp
(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 seconds
```

The `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:

```lisp
(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.

[get-internal-real-time]: http://www.lispworks.com/documentation/HyperSpec/Body/f_get_in.htm#get-internal-real-time

### 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))
; =>
2003
```

There'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`:

```lisp
; ...
        ,@(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:

```lisp
; ...
        ,(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:

```lisp
(iterate
  (repeat 20)
  (sleep (random 1.0))
  (timing real-time :per-iteration-into time)
  (averaging (to-seconds time)))
; =>
0.51555
```