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
On Fri, Apr 10, 2020 at 8:46 PM Alan Thompson <clooj...@gmail.com> wrote:
> 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 clojure@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+unsubscr...@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+unsubscr...@googlegroups.com.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/clojure/CAN67zA0wp8vv6xbWDAPTFNrz8CpcDOv7o0_eY9%3DYxYqNdZY1RQ%40mail.gmail.com
> <https://groups.google.com/d/msgid/clojure/CAN67zA0wp8vv6xbWDAPTFNrz8CpcDOv7o0_eY9%3DYxYqNdZY1RQ%40mail.gmail.com?utm_medium=email&utm_source=footer>
> .
>
--
You received this message because you are subscribed to the Google
Groups "Clojure" group.
To post to this group, send email to clojure@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+unsubscr...@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+unsubscr...@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/clojure/CADQBrAR0qGbHboZtiSvj1JhUf06HZ8jVP-zNoN3sr4PrDLEx0A%40mail.gmail.com.
