Clojurians Log v2

I’ve got a weird behavior (in Planck only, not w/ Lumo)

(defn bench [] (time (dotimes [_ 10000] (group-by odd? (range 256)))))
#'cljs.user/bench
cljs.user=> (dotimes [_ 10] (bench))
"Elapsed time: 1533.225609 msecs"
"Elapsed time: 1545.058830 msecs"
"Elapsed time: 1536.182743 msecs"
"Elapsed time: 1521.966733 msecs"
"Elapsed time: 1506.721830 msecs"
"Elapsed time: 1472.677051 msecs"
"Elapsed time: 1491.300766 msecs"
"Elapsed time: 1516.079173 msecs"
"Elapsed time: 1514.056357 msecs"
"Elapsed time: 1522.890919 msecs"
nil
cljs.user=> (bench)"Elapsed time: 1514.210034 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 1620.281140 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 1721.816597 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 1838.539985 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 2001.939968 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 2322.965899 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 2805.921760 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 3226.431841 msecs"
nil

calling (bench) at the top level seems to cause some kind of leak

I think Planck is monkey-patching the time measurement functions, so there might be a leak there :-)

@anmonteiro wouldn’t the leak occur when time is called in a loop too? (first part of the repl log above)

Node.js has its own high resolution timer so we don't need to do it in Lumo

Hah weird

I don't know how to answer that

Hopefully @mfikes will have an idea.

@anmonteiro have you moved to the US yet?

Not yet, looks like it's going to be in early January!

That is odd. I can’t repro it for some reason:

cljs.user=> (defn bench [] (time (dotimes [_ 10000] (group-by odd? (range 256)))#'cljs.user/bench
cljs.user=> (dotimes [_ 10] (bench))
"Elapsed time: 1159.593320 msecs"
"Elapsed time: 1144.919094 msecs"
"Elapsed time: 1157.564999 msecs"
"Elapsed time: 1123.972061 msecs"
"Elapsed time: 1139.588274 msecs"
"Elapsed time: 1152.520801 msecs"
"Elapsed time: 1137.451620 msecs"
"Elapsed time: 1146.951209 msecs"
"Elapsed time: 1143.448975 msecs"
"Elapsed time: 1143.177494 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 1189.568211 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 1159.490809 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 1135.291230 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 1132.313437 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 1136.998144 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 1205.367067 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 1144.274852 msecs"
nil
cljs.user=> (bench)
"Elapsed time: 1175.763460 msecs"
nil

Perhaps @cgrand isn't on the latest version?

@anmonteiro I tried on latest release and a build from master a couple of days old

I have noticed what appears to be a pattern where JavaScriptCore starts to slow down (and then speed up again), if it is either under memory pressure, or oddly decides to deopt things. So, what @cgrand shows is definitely something that can occur.

One example is (time (apply + (range 1e7))) seems to fit in something that JavaScriptCore boils down to native code, but with 1e8 it can slow down upon repeated invocations.

For example:

cljs.user=> (time (apply + (range 1e8)))
"Elapsed time: 555.519680 msecs"
4999999950000000
cljs.user=> (time (apply + (range 1e8)))
"Elapsed time: 1333.784931 msecs"
4999999950000000
cljs.user=> (time (apply + (range 1e8)))
"Elapsed time: 650.136291 msecs"
4999999950000000
cljs.user=> (time (apply + (range 1e8)))
"Elapsed time: 164.449090 msecs"
4999999950000000
cljs.user=> (time (apply + (range 1e8)))
"Elapsed time: 1387.819913 msecs”

hmm I’m not sure that’s the same case

I notice the slowdown only at top-level (but trying to fool that by wrapping in protective (#(…)) blankets is not enough)

so if I invoke (bench) at the top level it gets sloooow. Then if after that I invoke (bench) in a loop: it’s back to fast. Then top-level again: slooooow.

I’d like to understand the patterns in something like this:

cljs.user=> (dotimes [_ 15] (time (apply + (range 1e8))))
"Elapsed time: 92.477998 msecs"
"Elapsed time: 93.037535 msecs"
"Elapsed time: 96.071314 msecs"
"Elapsed time: 88.145049 msecs"
"Elapsed time: 110.345374 msecs"
"Elapsed time: 93.773480 msecs"
"Elapsed time: 145.159269 msecs"
"Elapsed time: 236.344057 msecs"
"Elapsed time: 543.034188 msecs"
"Elapsed time: 85.990809 msecs"
"Elapsed time: 1157.872663 msecs"
"Elapsed time: 600.583491 msecs"
"Elapsed time: 153.080935 msecs"
"Elapsed time: 1170.582053 msecs"
"Elapsed time: 1246.068331 msecs”

;;failed attempt to escape top-level:
cljs.user=> (#(= (bench) %) *1)
"Elapsed time: 2235.353784 msecs"
false
cljs.user=> (#(= (bench) %) *1)
"Elapsed time: 2906.238506 msecs"
false
;; loop again
cljs.user=> (dotimes [_ 10] (bench))"Elapsed time: 2881.619693 msecs"
"Elapsed time: 2030.329689 msecs"
"Elapsed time: 1557.854658 msecs"
"Elapsed time: 1454.047283 msecs"
"Elapsed time: 1453.595620 msecs"
"Elapsed time: 1446.568025 msecs"
"Elapsed time: 1467.628626 msecs"
"Elapsed time: 1476.907106 msecs"
"Elapsed time: 1462.299794 msecs"
"Elapsed time: 1460.685129 msecs"
nil
;; back to slow (picking up where it was slow, not rebuilding “slowness” from the last (fast) run)
cljs.user=> (#(nil? (bench)))"Elapsed time: 3659.887264 msecs"
true

@mfikes the difference between yours and mine is that yours degrades in dotimes while mine does not degrade in dotimes

Perhaps there is something wrong with Planck: This works consistently in http://clojurescript.io in Safari: (with-out-str (time (apply + (range 1e8))))

cljs.user=> (dotimes [_ 2] (bench))
"Elapsed time: 4572.871578 msecs"
"Elapsed time: 2918.273279 msecs” ; <- 2nd run gets better
nil
cljs.user=> (dotimes [_ 2] (bench))
"Elapsed time: 5467.805329 msecs"
"Elapsed time: 4465.643162 msecs"
nil
cljs.user=> (dotimes [_ 10] (bench))
"Elapsed time: 5442.148106 msecs"
"Elapsed time: 4066.061629 msecs"
"Elapsed time: 3183.890247 msecs"
"Elapsed time: 2285.270737 msecs"
"Elapsed time: 1986.569337 msecs"
"Elapsed time: 1875.215045 msecs"
"Elapsed time: 1888.828314 msecs"
"Elapsed time: 1942.992139 msecs"
"Elapsed time: 1674.563168 msecs"
"Elapsed time: 1571.186017 msecs”
nil
cljs.user=> (bench)
"Elapsed time: 6557.035676 msecs” ; <- so slooow again

Perhaps there is some leak in Planck—perhaps I have it inadvertently holding onto something in the JS engine.

I’ll log a ticket and dig into it.

ok thanks

https://github.com/mfikes/planck/issues/417

How are top-level input processed?

@cgrand Any form is compiled to JavaScript and then evaluated in the VM. If you pass -v to either Planck or Lumo, you will see the JavaScript emitted and evaluated.