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.
--
You received this message because you are subscribed to the Google
Groups "Clojure" group.
To post to this group, send email to [email protected]
Note that posts from new members are moderated - please be patient with your
first post.
To unsubscribe from this group, send email to
[email protected]
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 [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/clojure/CAN67zA0wp8vv6xbWDAPTFNrz8CpcDOv7o0_eY9%3DYxYqNdZY1RQ%40mail.gmail.com.
