Timing Code in ClojureScript

Here's a handy little ClojureScript macro that helps you time how long code blocks take. It's exactly like (clojure.core/time), in that it takes a code block and tells you how long it took to execute, but specially for ClojureScript it piggy-backs on the JavaScript console API, for pretty output in the inspector pane. You'd use it like this:

(console-time "Rendering Big Thing"
              (render-to-dom lots-of-data))

And the browser's inspector console will print out Rendering Big Thing: 10070.868ms when it's done.

How does it work? Well, it's really just wrapping a code block in two console API calls, .time(<label>) and .timeEnd(<label>). We could almost say:

(defmacro console-time
  [label & body]
  `(do
     (.time js/console ~label)
     ~@body
     (.timeEnd js/console ~label)))

...splicing the body between those calls. But that would have a flaw: instead of returning the body's result value, we're returning the result of console.timeEnd, which is always nil.

So we take a second pass:

(defmacro console-time
  [label & body]
  `(do
     (.time js/console ~label)
     ~@body
     (.timeEnd js/console ~label)
     ~@body))

It's pretty obvious that's wrong too - right return value, but it's executing the body twice. That's bad for performance, and outright broken if body contains side-effects¹.

There's nothing for it - we're going to have to run the block once, capture its return value, and return that captured result later.

To capture it, we'll have to create a temporary local var, with a guaranteed-unique name. We can do that by appending a hash symbol, as result#.

With that, the final code should make sense:

(defmacro console-time
  [label & body]
  `(do
     (.time js/console ~label)
     (let [result# (do ~@body)]
       (.timeEnd js/console ~label)
       result#)))

Remember if you're using this forreals, all ClojureScript macros must go in a Clojure file, and be imported with (refer-macros ...).

Footnotes