Clojure performance testing with macros

When changing some function in a way that has performance implications, I find myself doing this repeatedly:


(prn :function-sum (with-out-str (time (+ 1 1))))
0.3s

Adding all that code is tedious and I wanted an easy way to switch between an instrumented version and a normal defn.

This is what I want my macro to do - basically wrapping my function (+ 1 1) with a start and stop timers. 

(defn get-nano-now
  "time now in nanoseconds" 
  []
  (. System (nanoTime)))
(defn elapsed-time-mili
  "elapsed time from `start` in miliseconds
  expects `start` to be in nanoseconds" 
  [start]
  (/ (double (- (get-nano-now) start)) 1000000.0))
;;something like this:
(defn custom-defn []
  (let [start# (get-nano-now) 
        result (+ 1 1)]
    (prn (elapsed-time-mili start#))
    result))
(custom-defn)
0.3s

This is the macro I came up with:


(defmacro defn-t [name args body]
  `(def ~name
     (fn ~args
       (let [start# (get-nano-now)
             result# ~body]
         (prn (format "traced %s: took %s msec." ~name (elapsed-time-mili start#)))
         result#))))
0.1s

Now I can easily toggle the timer in my function just by adding -t:

(defn-t sum [a b]
  (+ a b))
0.1s
(sum 1 2)
0.3s

PS. How to debug it:


(clojure.pprint/pprint
  (macroexpand `(defn-t sum [a b] (+ a b)))) )
;;get the output of this running and figure out where the mistake is:
0.5s

If you clean up the output above of namespaces and autogenerated suffixes, it becomes easier to understand what happens at run time:

(clojure.pprint/pprint
  (macroexpand `(defn-t custom-sum [a b] (+ a b)))) )
;;becomes
(comment
(def
 sum
 (fn [a b]
   (let
   [start (get-nano-now)
    result (+ a b)]
   (prn (format"traced %s/%s took %s msec." *ns* 'custom-sum (elapsed-time-mili start)))
     result))))
0.5s
Runtimes (1)