Hi. I'm getting a three-fold difference in timing results when I add a
seemingly trivial println to observe what's going on. Consider:
(defmacro mytime1
"Returns execution time of expr in millisecs"
[expr]
`(let [time0# (. System nanoTime)
exprval# ~expr
time1# (/ (double (- (. System nanoTime) time0#)) 1000000.0)]
time1#))
(defmacro mytime2
"Prints out execution time of expr in millisecs and returns it"
[expr]
`(let [time0# (. System nanoTime)
exprval# ~expr
time1# (/ (double (- (. System nanoTime) time0#)) 1000000.0)]
(println "elapsed time (msec): " time1#)
time1#))
Timing macros mytime1 and mytime2 differ only in that mytime2 has the
println expression in the second last line. The println in mytime2
comes after time1# is assigned, so the println expression's execution
time shouldn't be counted. I confirmed this assumption by testing.
(mytime1 (+ 1 2 3)) and (mytime2 (+ 1 2 3)) both return values in the
0.05 to 0.08 msec range (on a single call, i.e. without Hotspot
optimization).
(defmacro myavgtime
"Calls timefunc on expr n times and returns average of the n
execution times"
[expr n timefunc]
`(loop [cumsum# 0 i# ~n]
(if (<= i# 0)
(/ cumsum# ~n )
(recur (+ cumsum# (~timefunc ~expr)) (dec i#) ))))
Results:
(myavgtime (+ 1 2 3) 1000 mytime1) returns average execution times in
the 0.0005 - 0.0008 msec range.
(myavgtime (+ 1 2 3) 1000 mytime2) returns average execution times in
the 0.0014 - 0.0018 msec range, after printing 1000 lines:
elapsed time (msec): 0.0870
elapsed time (msec): 0.0010
elapsed time (msec): 0.0020
elapsed time (msec): 0.0010
elapsed time (msec): 0.0010
...
<990 similar output lines not shown>
...
elapsed time (msec): 0.0010
elapsed time (msec): 0.0010
elapsed time (msec): 0.0010
elapsed time (msec): 0.0010
elapsed time (msec): 0.0010
So, using mytime2 with the myavgtime macro gives average execution
times for the expression (+ 1 2 3) of 2 to 3 times longer than when
using mytime1. Why is this? Does the JIT optimize differently with all
those println's when using mytime2? (Kind of "quantum mechanics-y" -
observing what's going on changes it.)
thanks for any insight here!
Matt
System specs:
MacBook Pro, Core2Duo 2.33GHz, 2GB RAM
OSX 10.5.8 Leopard
Clojure 1.1.0-alpha-SNAPSHOT
java version "1.6.0_15"
Java(TM) SE Runtime Environment (build 1.6.0_15-b03-226)
Java HotSpot(TM) 64-Bit Server VM (build 14.1-b02-92, mixed mode)
--~--~---------~--~----~------------~-------~--~----~
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
-~----------~----~----~----~------~----~------~--~---
