emacs.d/clones/lisp/stevelosh.com/blog/2016/10/iterate-timing/index.html

208 lines
14 KiB
HTML
Raw Normal View History

2022-10-07 15:47:14 +02:00
<!DOCTYPE html>
<html lang='en'><head><meta charset='utf-8' /><meta name='pinterest' content='nopin' /><link href='../../../../static/css/style.css' rel='stylesheet' type='text/css' /><link href='../../../../static/css/print.css' rel='stylesheet' type='text/css' media='print' /><title>Customizing Common Lisp&#039;s Iterate: Timing / Steve Losh</title></head><body><header><a id='logo' href='https://stevelosh.com/'>Steve Losh</a><nav><a href='../../../index.html'>Blog</a> - <a href='https://stevelosh.com/projects/'>Projects</a> - <a href='https://stevelosh.com/photography/'>Photography</a> - <a href='https://stevelosh.com/links/'>Links</a> - <a href='https://stevelosh.com/rss.xml'>Feed</a></nav></header><hr class='main-separator' /><main id='page-blog-entry'><article><h1><a href='index.html'>Customizing Common Lisp&#039;s Iterate: Timing</a></h1><p class='date'>Posted on October 10th, 2016.</p><p>This entry is the second in a series about customizing Common Lisp's <a href="https://common-lisp.net/project/iterate/">iterate</a>
library. The full series:</p>
<ul>
<li><a href="../../09/iterate-averaging/index.html">Averaging</a></li>
<li><a href="index.html">Timing</a></li>
</ul>
<p>This post will show how to make a <code>timing</code> 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 <a href="http://www.amazon.com/dp/1680500554/?tag=stelos-20">maze generation</a>.</p>
<ol class="table-of-contents"><li><a href="index.html#s1-end-result">End Result</a></li><li><a href="index.html#s2-code">Code</a><ol><li><a href="index.html#s3-argument-pairing">Argument Pairing</a></li><li><a href="index.html#s4-symbols-keywords">Symbols &amp; Keywords</a></li><li><a href="index.html#s5-variables">Variables</a></li><li><a href="index.html#s6-splicing">Splicing</a></li></ol></li><li><a href="index.html#s7-composing">Composing</a></li></ol>
<h2 id="s1-end-result"><a href="index.html#s1-end-result">End Result</a></h2>
<p>Before we look at the code, let's look at what we're aiming for:</p>
<pre><code><span class="code"><span class="paren1">(<span class="code"><i><span class="symbol">defun</span></i> to-seconds <span class="paren2">(<span class="code">internal-time-units</span>)</span>
<span class="paren2">(<span class="code">/ internal-time-units internal-time-units-per-second 1.0</span>)</span></span>)</span>
<span class="paren1">(<span class="code">iterate
<span class="paren2">(<span class="code">repeat 5</span>)</span>
<span class="paren2">(<span class="code">sleep <span class="paren3">(<span class="code">random 3.0</span>)</span></span>)</span>
<span class="paren2">(<span class="code">timing real-time <span class="keyword">:since-start-into</span> total-time
<span class="keyword">:per-iteration-into</span> loop-time</span>)</span>
<span class="paren2">(<span class="code">collect loop-time <span class="keyword">:into</span> loop-times</span>)</span>
<span class="paren2">(<span class="code">finally
<span class="paren3">(<span class="code">format t <span class="string">&quot;Individual times: ~S~%Total time: ~F seconds~%&quot;</span>
<span class="paren4">(<span class="code">mapcar #'to-seconds loop-times</span>)</span>
<span class="paren4">(<span class="code">to-seconds total-time</span>)</span></span>)</span></span>)</span></span>)</span>
<span class="comment">; =&gt;
</span>Individual times: <span class="paren1">(<span class="code">0.948 1.359 2.828 2.891 2.744</span>)</span>
Total time: 10.77 seconds</span></code></pre>
<p>The <code>timing</code> clause is what we'll be implementing.</p>
<h2 id="s2-code"><a href="index.html#s2-code">Code</a></h2>
<p>The code for <code>timing</code> 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:</p>
<pre><code><span class="code"><span class="paren1">(<span class="code"><i><span class="symbol">defmacro-clause</span></i> <span class="paren2">(<span class="code">TIMING time-type &amp;optional
SINCE-START-INTO since-var
PER-ITERATION-INTO per-var</span>)</span>
<span class="paren2">(<span class="code"><i><span class="symbol">let</span></i> <span class="paren3">(<span class="code"><span class="paren4">(<span class="code">timing-function <span class="paren5">(<span class="code">ecase time-type
<span class="paren6">(<span class="code"><span class="paren1">(<span class="code">real-time</span>)</span> #'get-internal-real-time</span>)</span>
<span class="paren6">(<span class="code"><span class="paren1">(<span class="code">run-time</span>)</span> #'get-internal-run-time</span>)</span></span>)</span></span>)</span>
<span class="paren4">(<span class="code">since-var <span class="paren5">(<span class="code">or since-var
<span class="paren6">(<span class="code">when <span class="paren1">(<span class="code">null per-var</span>)</span>
<span class="special">iterate::*result-var*</span></span>)</span></span>)</span></span>)</span></span>)</span>
<span class="paren3">(<span class="code"><i><span class="symbol">with-gensyms</span></i> <span class="paren4">(<span class="code">start-time current-time previous-time</span>)</span>
`<span class="paren4">(<span class="code"><i><span class="symbol">progn</span></i>
<span class="paren5">(<span class="code">with ,start-time = <span class="paren6">(<span class="code">funcall ,timing-function</span>)</span></span>)</span>
<span class="paren5">(<span class="code">for ,current-time = <span class="paren6">(<span class="code">funcall ,timing-function</span>)</span></span>)</span>
,@<span class="paren5">(<span class="code">when since-var
`<span class="paren6">(<span class="code"><span class="paren1">(<span class="code">for ,since-var = <span class="paren2">(<span class="code">- ,current-time ,start-time</span>)</span></span>)</span></span>)</span></span>)</span>
,@<span class="paren5">(<span class="code">when per-var
`<span class="paren6">(<span class="code"><span class="paren1">(<span class="code">for ,previous-time <span class="keyword">:previous</span> ,current-time
<span class="keyword">:initially</span> ,start-time</span>)</span>
<span class="paren1">(<span class="code">for ,per-var = <span class="paren2">(<span class="code">- ,current-time ,previous-time</span>)</span></span>)</span></span>)</span></span>)</span></span>)</span></span>)</span></span>)</span></span>)</span></span></code></pre>
<p>Times are recorded in &quot;internal time units&quot; to be consistent with other Common
Lisp functions like <a href="http://www.lispworks.com/documentation/HyperSpec/Body/f_get_in.htm#get-internal-real-time">get-internal-real-time</a>. Some implementations will be
more precise than others.</p>
<h3 id="s3-argument-pairing"><a href="index.html#s3-argument-pairing">Argument Pairing</a></h3>
<p>One thing that I sometimes find annoying about <code>iterate</code> clauses is that they
must contain <em>pairs</em> of arguments. You can't have an odd number of arguments,
like:</p>
<pre><code>(TIMING &amp;optional SINCE-START since-var PER-ITERATION per-var).</code></pre>
<p>Often, however, you can make the best of this restriction and come up with
something at least <em>moderately</em> useful to use as an extra argument to pad things
out. For the <code>timing</code> clause I decided to make the second argument define which
type of time to measure (process run time or wall clock time).</p>
<h3 id="s4-symbols-keywords"><a href="index.html#s4-symbols-keywords">Symbols &amp; Keywords</a></h3>
<p>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 <code>real-time</code> and
<code>run-time</code> symbols from this package, not just the <code>timing</code> symbol. This is
a little annoying, but I like how it looks when used.</p>
<p>Another option would be to change these to keyword symbols, so you would say
<code>(timing :real-time ...)</code> instead. Or you could just support both (<code>ecase</code>
makes this easy).</p>
<p>Note the use of <code>ecase</code> when checking the time type to signal an error at
macroexpansion time with a helpful message if the user passed something
incorrect:</p>
<pre><code>(iterate (timing foo :since-start-into some-var))
; =&gt;
debugger invoked on a SB-KERNEL:CASE-FAILURE in thread
#&lt;THREAD &quot;main thread&quot; RUNNING {10028F7473}&gt;:
FOO fell through ECASE expression. Wanted one of (REAL-TIME RUN-TIME).
...</code></pre>
<h3 id="s5-variables"><a href="index.html#s5-variables">Variables</a></h3>
<p>To fit with the general pattern of <code>iterate</code> 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:</p>
<pre><code>(macroexpand-iterate '(timing real-time))
; =&gt;
(PROGN
(WITH #:START-TIME516 = (FUNCALL #&lt;CLOSURE GET-INTERNAL-REAL-TIME&gt;))
(FOR #:CURRENT-TIME517 = (FUNCALL #&lt;CLOSURE GET-INTERNAL-REAL-TIME&gt;))
(FOR ITERATE::*RESULT-VAR* = (- #:CURRENT-TIME517 #:START-TIME516)))
(iterate (repeat 1) (sleep 2.0) (timing real-time))
; =&gt;
2003</code></pre>
<p>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 <code>iterate::*result-var*</code> in their loop
body like any other variable, so this will do the right thing in that case (even
if that case <em>is</em> horrifying).</p>
<p>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:</p>
<pre><code>(macroexpand-iterate
'(timing real-time :since-start-into x))
; =&gt;
(PROGN
(WITH #:START-TIME525 = (FUNCALL #&lt;CLOSURE GET-INTERNAL-REAL-TIME&gt;))
(FOR #:CURRENT-TIME526 = (FUNCALL #&lt;CLOSURE GET-INTERNAL-REAL-TIME&gt;))
(FOR X = (- #:CURRENT-TIME526 #:START-TIME525)))
(macroexpand-iterate
'(timing real-time :per-iteration-into x))
; =&gt;
(PROGN
(WITH #:START-TIME528 = (FUNCALL #&lt;CLOSURE GET-INTERNAL-REAL-TIME&gt;))
(FOR #:CURRENT-TIME529 = (FUNCALL #&lt;CLOSURE GET-INTERNAL-REAL-TIME&gt;))
(FOR #:PREVIOUS-TIME530 :PREVIOUS #:CURRENT-TIME529 :INITIALLY
#:START-TIME528)
(FOR X = (- #:CURRENT-TIME529 #:PREVIOUS-TIME530)))</code></pre>
<h3 id="s6-splicing"><a href="index.html#s6-splicing">Splicing</a></h3>
<p>Another thing to note is the use of <code>,@</code> to splice the appropriate clauses into
the final <code>progn</code>:</p>
<pre><code><span class="code"><span class="comment">; ...
</span> ,@<span class="paren1">(<span class="code">when since-var
`<span class="paren2">(<span class="code"><span class="paren3">(<span class="code">for ,since-var = <span class="paren4">(<span class="code">- ,current-time ,start-time</span>)</span></span>)</span></span>)</span></span>)</span>
,@<span class="paren1">(<span class="code">when per-var
`<span class="paren2">(<span class="code"><span class="paren3">(<span class="code">for ,previous-time <span class="keyword">:previous</span> ,current-time
<span class="keyword">:initially</span> ,start-time</span>)</span>
<span class="paren3">(<span class="code">for ,per-var = <span class="paren4">(<span class="code">- ,current-time ,previous-time</span>)</span></span>)</span></span>)</span></span>)</span>
<span class="comment">; ...</span></span></code></pre>
<p>For the <code>since-var</code> clause we could have gotten away with just using a plain <code>,</code>
and returning the <code>for</code> clause itself:</p>
<pre><code><span class="code"><span class="comment">; ...
</span> ,<span class="paren1">(<span class="code">when since-var
`<span class="paren2">(<span class="code">for ,since-var = <span class="paren3">(<span class="code">- ,current-time ,start-time</span>)</span></span>)</span></span>)</span>
<span class="comment">; ...</span></span></code></pre>
<p>This would work, but when <code>since-var</code> is null (when the user wants only the
per-iteration time) the <code>when</code> statement would evaluate to <code>nil</code>, and would
leave a stray <code>nil</code> in the <code>progn</code>:</p>
<pre><code>(macroexpand-iterate
'(timing real-time :per-iteration-into x))
; =&gt;
(PROGN
(WITH #:START-TIME531 = (FUNCALL #&lt;CLOSURE GET-INTERNAL-REAL-TIME&gt;))
(FOR #:CURRENT-TIME532 = (FUNCALL #&lt;CLOSURE GET-INTERNAL-REAL-TIME&gt;))
NIL
(FOR #:PREVIOUS-TIME533 :PREVIOUS #:CURRENT-TIME532 :INITIALLY
#:START-TIME531)
(FOR X = (- #:CURRENT-TIME532 #:PREVIOUS-TIME533)))</code></pre>
<p>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 <em>right</em> and not
be lazy.</p>
<p>Also notice that we don't define the <code>previous-time</code> 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.</p>
<h2 id="s7-composing"><a href="index.html#s7-composing">Composing</a></h2>
<p>One of the great things about <code>iterate</code> is that the extensions you make can use
each other. For example, we can use last post's <code>averaging</code> clause with the one
we just made to calculate the average time per loop iteration:</p>
<pre><code><span class="code"><span class="paren1">(<span class="code">iterate
<span class="paren2">(<span class="code">repeat 20</span>)</span>
<span class="paren2">(<span class="code">sleep <span class="paren3">(<span class="code">random 1.0</span>)</span></span>)</span>
<span class="paren2">(<span class="code">timing real-time <span class="keyword">:per-iteration-into</span> time</span>)</span>
<span class="paren2">(<span class="code">averaging <span class="paren3">(<span class="code">to-seconds time</span>)</span></span>)</span></span>)</span>
<span class="comment">; =&gt;
</span>0.51555</span></code></pre>
</article></main><hr class='main-separator' /><footer><nav><a href='https://github.com/sjl/'>GitHub</a><a href='https://twitter.com/stevelosh/'>Twitter</a><a href='https://instagram.com/thirtytwobirds/'>Instagram</a><a href='https://hg.stevelosh.com/.plan/'>.plan</a></nav></footer></body></html>