# HG changeset patch # User Steve Losh # Date 1476111088 0 # Node ID 653f385c1bee15d8d3bd2060ff073eba312a6425 # Parent fdf01e99fd51930479105db9adfa0763a88533ed Add timing entry diff -r fdf01e99fd51 -r 653f385c1bee Makefile --- a/Makefile Mon Oct 10 14:26:27 2016 +0000 +++ b/Makefile Mon Oct 10 14:51:28 2016 +0000 @@ -16,7 +16,7 @@ rm -rf public serve: - hugo server -t stevelosh + hugo server -t stevelosh -D deploy: public/index.html rsync -avz ./public/ sl:/var/www/stevelosh.com diff -r fdf01e99fd51 -r 653f385c1bee content/blog/2016/09/iterate-averaging.markdown --- a/content/blog/2016/09/iterate-averaging.markdown Mon Oct 10 14:26:27 2016 +0000 +++ b/content/blog/2016/09/iterate-averaging.markdown Mon Oct 10 14:51:28 2016 +0000 @@ -19,6 +19,11 @@ I figured I'd post about them in case someone else is looking for examples of how to write their own `iterate` clauses and drivers. +This entry is the first in a series: + +* [Averaging](/blog/2016/09/iterate-averaging/) +* [Timing](/blog/2016/10/iterate-timing/) + This first post will show how to make a `averaging` clause that keeps a running average of a given expression during the loop. I've found it handy in a couple of places. diff -r fdf01e99fd51 -r 653f385c1bee content/blog/2016/10/iterate-timing.markdown --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/content/blog/2016/10/iterate-timing.markdown Mon Oct 10 14:51:28 2016 +0000 @@ -0,0 +1,237 @@ ++++ +title = "Customizing Common Lisp's Iterate: Timing" +snip = "How long is this loop?" +date = 2016-10-10T14:50:00Z +draft = false + ++++ + +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/ + +
+ +## 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 + #: + 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 #)) + (FOR #:CURRENT-TIME517 = (FUNCALL #)) + (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 #)) + (FOR #:CURRENT-TIME526 = (FUNCALL #)) + (FOR X = (- #:CURRENT-TIME526 #:START-TIME525))) + +(macroexpand-iterate + '(timing real-time :per-iteration-into x)) +; => +(PROGN + (WITH #:START-TIME528 = (FUNCALL #)) + (FOR #:CURRENT-TIME529 = (FUNCALL #)) + (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 #)) + (FOR #:CURRENT-TIME532 = (FUNCALL #)) + 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 +```