Clojurians Log v2

It is reasonably common with Clojure/Java in a REPL to compile a function, run an expression using it with time to see some relatively long first run time, then you repeat it a few times, and if/when the JIT kicks in, you get a shorter run time, and continued runs repeat (with some variation) around that new lower run time.

I think I am seeing a case where, consistently, the first run of a function after defining it is faster than later runs, i.e. the pattern I can repeat is: define the function, first time run is fast, second through N-th time runs are relatively consistent times, about 3x longer than the first.

Perhaps a case where JIT is kicking in and making things worse?

it can happen

wouldn't say it's "reasonably common", but it's certainly possible

do you have an example?

Function foo2 on this doc page: https://clojure.org/reference/java_interop#primitives

uh, that looks innocent enough :)

Seen it with both AdoptOpenJDK 1.8.0 and 11 on macOS 10.13.6, Clojure 1.10.1, I doubt any special JVM options.

just did a very unscientific run and it behaves as I'd expect on my machine (first run takes 1.8s, second 0.4, third 0.2, and then it oscillates between 0.14 and 0.16)

would be interesting to see the jit log on yours

getting there ....

You mean the output when -XX:+PrintCompilation is enabld?

https://github.com/jafingerhut/leeuwenhoek/blob/master/doc/runs-slower-after-first.md

have you tried with Criterium, just for consistency?

I have now, and as I would have expected, it is consistent with the longer runs that occur not on the first time.

how are your fans? could power management be throttling things back as there is more activity?

Fan behavior is not changing between these runs, and each one of them is sub-second. Note that I can, after getting the longer run times, do the defn over again, and the first run after that is fast again, once, before repeated runs going back to slower speed.

@andy.fingerhut it reminds me of something but I can’t remember exactly what. Two things: 1/ Do you see the same thing if you replace int by long? 2/ if you (def my-test #(foo2 1000000)) and then time my-test?

Will try those out soon here...

Replacing two occurrences of (int ...) with (long ...) gives same behavior.

Same fast-on-first-run, slower-on-second-and-later-runs behavior with your #2 suggestions. Goes back to one fast run if I re-do defn and def, but does not if I only re-evalute the def

And if the def includes the call to time?

trying soon, but may be off-line for 20 mins or so.

same behavior

@bronsa Out of curiosity what OS and JDK was your experiment on? I have yet to find a combo that doesn't exhibit this behavior, so far.

I got something vaguely similar, an undulating pattern of runtimes, where it settles down around 0.20-0.40 for me and after some number of calls might jump back up to 0.70-1.0 for a call(maybe triggering a gc?), then back down

I do not see how there is anything to GC here

but can try adding debug logging of occurrences of GC to my JVM startup options

@hiredman What OS and JDK are you running?

but for the most part I see the first call slow, then faster and faster

linux, I've tried a few jvms, openjdk13, zulu 8, zulu 11, and corretto 11 (I think those are all openjdk based)

if you want to exclude GC from suspicion you can use Epsilon GC

I have enabled GC logging, and it does not occur during my tests

That simple function shouldn't be allocating any memory.

I also tried zulu 8, zulu 11, corretto 11 on Ubuntu 18.04 VM running on my local Mac laptop, and see the same behavior I have seen on other OS/JDK combos I have tried. I checked in a one-line shell script that runs a short Clojure program to automate this, since it was getting a little tedious to repeat by hand: https://github.com/jafingerhut/leeuwenhoek/blob/master/tryme.sh

I should probably try a bare metal Linux machine at some point.