You are trusting nanoTime to actually return values that are useful! They might be completely useless for your timing purposes. :-) It all depends on the hardware you are running.
Read the spec: http://java.sun.com/j2se/1.5.0/docs/api/java/lang/System.html#nanoTime() The reason for this is that the granularity of the system timer can be 1ms, if you are running a Linux kernel that ticks 1000 times every second, then you will get nanoTime samples spaced 1ms apart. Eh... (On even older systems you have 100 ticks per second.) Of course modern cpus usually have a counter in the cpu-hardware that updates with every hardware clock tick. This can usually be recalculated into nano-time. But there is no guarantee that you will be actually executing at any time, the OS might execute sometime else. Also the cpu might enter low power mode and stall the clock cycles and suddenly you have bad resolution again. To be on the safe side, the inner loop should run many, many times so that the measured execution time is in several seconds and use System.currentTimeMillis to do the measuring. In more complex tests that actually work with the disk, you also have to run the test once to warm up all the disk caches. //Fredrik 2009/9/30 Matt Brown <mrbrow...@gmail.com>: > > Hi. > > Thanks all, for your comments. > >> You need to use a bigger number than 1000 for these results to be meaningful. > > Out of curiousity, why is this? > Does the JIT do something different after 1000 iterations? > Or is the concern simply that the variance of the mean estimate is too > high with 1000 vs. 10^6 iterations (due to OS background processes, > etc.)? I originally reported ranges for average execution times (over > about a dozen runs) to address this particular concern. > >> FWIW, I've run both on my Toshiba dual core laptop with ubuntu, and >> they return approximately the same values. >> >> (and there is some JIT trickery going on, as I got: >> user=> (myavgtime (+ 1 2 3) 1000 mytime1) >> (myavgtime (+ 1 2 3) 1000 mytime1) >> 0.0029811580000000306 >> user=> (myavgtime (+ 1 2 3) 100000 mytime1) >> (myavgtime (+ 1 2 3) 100000 mytime1) >> 0.0017426112899993846 >> user=> (myavgtime (+ 1 2 3) 1e8 mytime1) >> (myavgtime (+ 1 2 3) 1e8 mytime1) >> 0.0015456479935035251 >> >> Although the last one ran for quite a bit longer than ,0015) > > Thanks for posting this! > One explanation for a decreasing mean execution time with an > increasing number of iterations is this: The first iteration's > execution time is relatively large because it's not JIT optimized > (0.018 msec on my system). Increasing the number of iterations means > you're averaging a larger number of small, JIT optimized individual > execution times (reported as 0.000-0.001 msec on my system) into that > initial larger value. The mean therefore becomes asymptotically > smaller with larger numbers of iterations. Is there something else > going on here as well though (eg: JIT stuff)? > > Using a million iterations, I got: > (myavgtime (+ 1 2 3) 1e6 mytime1) -> 0.00027 - 0.00029 msec (over a > dozen repeats) > (myavgtime (+ 1 2 3) 1e6 mytime2) -> 0.00068 msec (single run, > printing 10^6 lines takes a long time, I was too impatient for > repeats) > > So, using mytime1 is still just over 2x faster than mytime2 with 10^6 > iterations. > > cheers > Matt > >> >> On Sep 29, 12:08 pm, Matt <mrbrow...@gmail.com> wrote: >> >> > 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 -~----------~----~----~----~------~----~------~--~---
