The other day I wanted a simple way to find some slow Clojure code. I could have used clj-async-profiler but I wrote this bit of code instead.

(def ^:dynamic *trace* (atom nil))

(defmacro with-trace
  [& body]
  `(binding [*trace* (atom {:labels [] :times []})]
     ~@body))

(defmacro with-timer
  [label & body]
  `(let [; add the new label to the stack
         x# (swap! *trace* update :labels conj ~label) 
         ; store the start time
         start# (System/nanoTime) 
         ; run the code being timed and save the return value
         r# (do ~@body) 
         ; calc the duration
         duration# (/ (- (System/nanoTime) start#) 1000000.0)] 
     ; add the duration to the :times section
     ; pop the label
     (swap! *trace* (fn [x#]
                      (-> x#
                          (update :times conj [(get x# :labels) duration#])
                          (update :labels pop))))
     ; don't forget the return value. 
     r#))

(defn get-trace
  []
  @*trace*)
        

Example usage:

(with-trace
  (with-timer :a
    (Thread/sleep 20)
    (with-timer :b
      (Thread/sleep 10)
      (with-timer :c
        (Thread/sleep 30))))
  (with-timer :d
    (Thread/sleep 200))
  (prn (get-trace)))
        

Example usage:

([(:d) 205.122625] 
 [(:a) 73.29775]
 [(:b :a) 47.705291] 
 [(:c :b :a) 35.056167])

How it works

The with-trace macro sets up the dynamic scope variable with a fresh atom to hold the state over time. It stores :labels and :times. The former stores a stack labels from the with-timer sections. The latter stores how long each with-timer section took to execute along with the stack of labels.