Clojure: Simple expression benchmark test

benchmark.clj

(defmacro c-time
  "Time an expression. Returns the time in milliseconds
   Complexity: O(1)
   - expr: an expression (not a lambda)"
  [expr]
  `(let [start# (. System (nanoTime))
         ret# ~expr]
     (/ (double (- (. System (nanoTime)) start#)) 1000000.0)))

(defmacro benchmark
  "Benchmark an expression. To reduce error and variation,
   it will average the time it took to run. If there is still
   too much variation, you can increase the number of iterations
   by specifying the 'times' argument.
   Complexity: O(n)
   - expr: an expression (not a lambda!)
   - times: the number of times to record and average
   - warmup-times: the number of times to run without recording results
   - clean: run garbage collector to have more consistent tests"
  ([expr] `(benchmark ~expr 1000))
  ([expr times] `(benchmark ~expr ~times 10))
  ([expr times warmup-times] `(benchmark ~expr ~times ~warmup-times false))
  ([expr times warmup-times clean] 
   `(let [func# (fn [] ~expr)]
      (when ~clean
        (System/gc))
      (dotimes [_# ~warmup-times] ;; warm up
        (c-time (func#)))
      (letfn [(d-time# [f# t# acc#] ;; average results, lower error margin
                (if (> t# 0)
                  (recur f# (- t# 1) (+ acc# (c-time (f#)))) 
                  acc#))]
        (let [avg-time# (/ (d-time# func# ~times 0) ~times)]
          (prn (format "Average elapsed time (%d times): %.10f msecs" ~times avg-time#))
          avg-time#)))))

tutorial.md

Tutorial

In this example, we'll be comparing a slow filter function with the built in function (BIF).

;; the slow filter function
(defn c-filter-recur
  ([pred items] (c-filter-recur pred (seq items) '()))
  ([pred items acc]
   (cond
     (empty? items) '()
     (pred (first items)) (recur pred (rest items) (cons (first items) acc))
     :else (recur pred (rest items) acc))))

At first we might want to use the BIF time.

(def numbers (take 100 (repeatedly #(rand-int 42))))
(prn "recur")
(time (c-filter-recur even? numbers))
(prn "BIF")
(time (filter even? numbers))

example output:
"lazy"
"Elapsed time: 0.912789 msecs"
"BIF"
"Elapsed time: 0.021634 msecs"

If we run this more than once, we see that the time elapsed varies quite a bit. So, to solve this error margin, we can use benchmark to take an average of multiple recorded times. Here is an example.

(def numbers (take 100 (repeatedly #(rand-int 100))))
(prn "recur")
(benchmark (c-filter-recur even? numbers))
(prn "BIF")
(benchmark (filter even? numbers))

example output:
"recur"
"Average elapsed time (1000 times): 0.0212918570 msecs"
"BIF"
"Average elapsed time (1000 times): 0.0002555670 msecs"

With benchmark we can see that there is less variation. However, you will probably see quicker elapsed time because of the warm up procedure. Warmed up functions typically run faster.

Tip: See the documentation in benchmark.clj for more options like customizing the number of recorded times, number of warm up times, and using the garbage collector.

If you are interested in using benchmark directly on a function, check out the code I wrote before combining these two. A macro benchmark for expressions and benchmark* for functions.

(defmacro c-time
  "Time an expression. Returns the time in milliseconds
   Complexity: O(1)
   - expr: an expression (not a lambda)"
  [expr]
  `(let [start# (. System (nanoTime))
         ret# ~expr]
     (/ (double (- (. System (nanoTime)) start#)) 1000000.0)))

(defn benchmark*
  "Benchmark a function. To reduce error and variation,
   it will average the time it took to run. If there is still
   too much variation, you can increase the number of iterations
   by specifying the 'times' argument. 
   Complexity: O(n) where n is times
   - func: a function, a lambda counts too
   - times: the number of times to record and average
   - clean: run garbage collector to have more consistent tests"
  [func times clean]
  ;; option to garbage clean for more consistent checks
  (when clean
    (System/gc))
  ;; warm up
  (dotimes [_# 10]
    (c-time (func)))
  ;; lower error margin through averaging
  (letfn [(d-time [f t acc]
            (if (> t 0)
              (recur f (- t 1) (+ acc (c-time (f)))) acc))]
    (let [avg-time (/ (d-time func times 0) times)]
      (prn (format "Average elapsed time (%d times): %.10f msecs" times avg-time))
      avg-time)))


(defmacro benchmark
  "Benchmark an expression. To reduce error and variation,
   it will average the time it took to run. If there is still
   too much variation, you can increase the number of iterations
   by specifying the 'times' argument.
   Complexity: O(n) where n is times
   - expr: an expression (not a lambda!)
   - times: the number of times to record and average
   - clean: run garbage collector to have more consistent tests"
  ([expr] `(benchmark ~expr 1000))
  ([expr times] `(benchmark ~expr ~times false))
  ([expr times clean] `(benchmark* (fn [] ~expr) ~times ~clean)))