Strange result for clojure.core/time

[Alan Thompson]

I was doing some macro work and was curious about the cost of an inline `eval` vs compiled code.  I tried to time it with `clojure.core/time` and got results I can't explain:

(println :eval-time)
(time
  (do
    (println (eval (quote (+ 40 0))))
    (println (eval (quote (+ 40 1))))
    (println (eval (quote (+ 40 2))))
    (println (eval (quote (+ 40 3))))
    (println (eval (quote (+ 40 4))))))

:eval-time
40
41
42
43
44
"Elapsed time: 0.922536 msecs"

On a modern computer, this is an insanely long amount of time. And yes, it is approx 5x longer than doing just one line of the above.  I also tried it without the eval:

(println :add-time)
(time
  (do
    (println (+ 30 0))
    (println (+ 30 1))
    (println (+ 30 2))
    (println (+ 30 3))
    (println (+ 30 4))))

:add-time
30
31
32
33
34
"Elapsed time: 0.01344 msecs"

Still seems pretty slow to just print 5 lines with a single addition each.

The `time` macro is very simple, and is often used as introductory example of how macros work and when they are needed:

(defmacro time
  "Evaluates expr and prints the time it took.  Returns the value of
 expr."
  {:added "1.0"}
  [expr]
  `(let [start# (. System (nanoTime))
         ret# ~expr]
     (prn (str "Elapsed time: " (/ (double (- (. System (nanoTime)) start#)) 1000000.0) " msecs"))
     ret#))

I coincidentally had a homegrown timer available with nearly identical code.  It has results:

(prof/with-timer-print :add-prof
  (do
    (println (+ 10 0))
    (println (+ 10 1))
    (println (+ 10 2))
    (println (+ 10 3))
    (println (+ 10 4))))

10

11
12
13
14
:with-timer-print :add-prof     0.000048

and

(prof/with-timer-print :eval-prof
  (do
    (println (eval (quote (+ 20 0))))
    (println (eval (quote (+ 20 1))))
    (println (eval (quote (+ 20 2))))
    (println (eval (quote (+ 20 3))))
    (println (eval (quote (+ 20 4))))))

20

21
22
23
24
:with-timer-print :eval-prof     0.001041

So we see the times are much, much shorter.  The timing code is nearly identical to clojure.core/time:

(defmacro with-timer-result
  "Times execution of Clojure forms, returning a result map like:
      {:result result  :seconds seconds} "
  [& forms]
  `(let [start#   (System/nanoTime)
         result#  (do ~@forms)
         stop#    (System/nanoTime)
         elapsed# (double (- stop# start#))
         seconds# (/ elapsed# 1e9)]
     {:result  result#
      :seconds seconds#}))

(defmacro with-timer-print
  "Times execution of Clojure forms, printing the result to the screen. "
  [id & forms]
  (when-not (keyword? id)
    (throw (ex-info "id must be a keyword" (vals->map id))))
  `(let [result-map# (with-timer-result ~@forms)]
     (println (format ":with-timer-print %s %12.6f" ~id (grab :seconds result-map#)))
     (grab :result result-map#)))

Does anyone have an idea of why `clojure.core/time` gives such insanely inflated results?

Alan

PS.  I ran the above 4 sequences multiple times using lein-test-refresh, and these were the shortest I could get.  I'm pretty confident the answer is not loading, compiling, or JIT related.

[Paul Stadig]

The output of `time` is in milliseconds and the output of `with-timer-print` is in seconds. So to make them comparable:

`time` 0.01344 msec

`time` with eval 0.922536 msec

`with-timer-print` 0.048 msec

`with-timer-print` with eval 1.041 msec

The `with-timer-print` version is slower, and I suspect it is the use of `format` instead of `str`.

Paul

--
You received this message because you are subscribed to the Google
Groups "Clojure" group.
To post to this group, send email to clo...@googlegroups.com
Note that posts from new members are moderated - please be patient with your first post.
To unsubscribe from this group, send email to
clojure+u...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/clojure?hl=en
---
You received this message because you are subscribed to the Google Groups "Clojure" group.
To unsubscribe from this group and stop receiving emails from it, send an email to clojure+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/clojure/CAN67zA0wp8vv6xbWDAPTFNrz8CpcDOv7o0_eY9%3DYxYqNdZY1RQ%40mail.gmail.com.

[Alan Thompson]

I now feel like Homer Simpson.....  Doh!

Alan

To view this discussion on the web visit https://groups.google.com/d/msgid/clojure/CADQBrAR0qGbHboZtiSvj1JhUf06HZ8jVP-zNoN3sr4PrDLEx0A%40mail.gmail.com.