The most naive (but oh-so-convenient) way to benchmark something you've just wrote is to wrap your code in a time macro. You'll also have to wrap the code in dotimes so that it gets executed enough times for JIT to trigger and for the measurement setup overhead to be amortized:
user=> (time (dotimes [_ 1e6] (reduce + (map #(/ % 100.0) (range 100))))) "Elapsed time: 1718.769042 msecs" nil
This works; however, doing it this way causes two mild annoyances:
dotimes? We usually have an idea of how long we want the benchmark to run (say, a few seconds), but don't know from the get-go how many times should the benchmarked code be executed to achieve that running time.
Both of these irritations can be solved by the following custom macro that I use for quick-and-dirty benchmarking when I'm in the active process of modifying the code. Adding it to the system-wide profile in Leiningen or tools.deps (see, for example, how Sean Corfield does it) will make it readily available during the development of any project of yours.
NB: you should absolutely use Criterium or JMH to obtain accurate results once you are done changing the code. The following macro adds convenience during active development but does not replace proper benchmarking tools. It is also not suitable for any kind of microbenchmarking.
(let [time* (fn [^long duration-in-ms f] (let [^com.sun.management.ThreadMXBean bean (java.lang.management.ManagementFactory/getThreadMXBean) bytes-before (.getCurrentThreadAllocatedBytes bean) duration (* duration-in-ms 1000000) start (System/nanoTime) _ (f) delta (- (System/nanoTime) start) deadline (+ start duration) tight-iters (max (quot (quot duration delta) 10) 1)] (loop [i 1] (let [now (System/nanoTime)] (if (< now deadline) (do (dotimes [_ tight-iters] (f)) (recur (+ i tight-iters))) (let [i' (double i) bytes-after (.getCurrentThreadAllocatedBytes bean) t (/ (- now start) i')] (println (format "Time per call: %s Alloc per call: %,.0fb Iterations: %d" (cond (< t 1e3) (format "%.0f ns" t) (< t 1e6) (format "%.2f us" (/ t 1e3)) (< t 1e9) (format "%.2f ms" (/ t 1e6)) :else (format "%.2f s" (/ t 1e9))) (/ (- bytes-after bytes-before) i') i))))))))] (defmacro time+ "Like `time`, but runs the supplied body for 2000 ms and prints the average time for a single iteration. Custom total time in milliseconds can be provided as the first argument." [?duration-in-ms & body] (let [[duration body] (if (integer? ?duration-in-ms) [?duration-in-ms body] [2000 (cons ?duration-in-ms body)])] `(~time* ~duration (fn  ~@body)))))
It may look like there's a lot going on here, but the logic is quite straightforward:
time+ is identical to how
time is used, except that the repetition
is performed automatically:
user=> (time+ (reduce + (map #(/ % 100.0) (range 100)))) Time per call: 1.78 us Alloc per call: 6,320b Iterations: 1122541 nil
After running the code for 2 seconds,
time+ prints the time and allocated
bytes per iteration, and the number of iterations. You can specify the total
time in milliseconds as the first argument to the macro:
user=> (time+ 5000 (Thread/sleep 10)) Time per call: 12.26 ms Alloc per call: 1b Iterations: 430 nil