Fork me on GitHub
#clojure-dev
<
2019-08-21
>
andy.fingerhut16:08:57

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.

andy.fingerhut16:08:02

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.

andy.fingerhut16:08:19

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

bronsa16:08:35

it can happen

bronsa16:08:55

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

bronsa16:08:58

do you have an example?

bronsa16:08:51

uh, that looks innocent enough :)

andy.fingerhut16:08:54

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.

bronsa16:08:36

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)

bronsa16:08:50

would be interesting to see the jit log on yours

andy.fingerhut16:08:38

getting there ....

andy.fingerhut16:08:22

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

schmee17:08:43

have you tried with Criterium, just for consistency?

andy.fingerhut18:08:50

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

hiredman18:08:51

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

andy.fingerhut18:08:58

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.

cgrand18:08:14

@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?

andy.fingerhut18:08:50

Will try those out soon here...

andy.fingerhut18:08:44

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

andy.fingerhut18:08:07

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

cgrand18:08:34

And if the def includes the call to time?

andy.fingerhut18:08:44

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

andy.fingerhut19:08:13

@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.

hiredman19:08:57

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

andy.fingerhut19:08:26

I do not see how there is anything to GC here

andy.fingerhut19:08:44

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

andy.fingerhut19:08:55

@hiredman What OS and JDK are you running?

hiredman19:08:10

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

hiredman19:08:02

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

schmee19:08:36

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

andy.fingerhut19:08:56

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

andy.fingerhut20:08:09

That simple function shouldn't be allocating any memory.

andy.fingerhut21:08:22

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

andy.fingerhut21:08:55

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