Clojurians Log v2

I have tried an Amazon EC2 Ubuntu 18.04 Linux t2.micro instance running OpenJDK 11 and seen the same behavior, running the tryme.sh script

I'm sure it has something to do with opt and deopt of that loop, but you're not running with enough debug stuff on in the jvm to tell

I've seen this before, don't remember what in particular

you need to actually have it print all the asm stuff probably

I can set that up and collect that data, and give a link to it later.

well, I don't have time to look at it, but that's what I'd do

From what I saw doing it once earlier today, I had the impression that it was optimizing up to 'level 4' at some point, and that was when it got slower.

that's tier 4, not level 4

Sure, not expecting you to dive in to the data, but someone else might see something I don't.

it could be when it does the on-stack replacement it finds something much faster but then deopts at the termination condition or something

just tweet it to https://twitter.com/shipilev, he'll probably tell you in 5 min

Thanks. I may do that once I have something with a JVM byte code listing and JIT logging enabled.

Good news, Alex, I saw your email message to the Clojure Google group, for the first time in a while.

@andy.fingerhut your loop is in return position and returns a primitive, the function return type is object, this return type mismatch is the root of the issue: 1/ Repro of your case:

(defn foo2 [n]
  (let [n (int n)]
    (loop [i (int 0)]
      (if (< i n)
        (recur (inc i))
        i))))
#'user/foo2
user=> (time (foo2 100000000))
"Elapsed time: 53.865585 msecs"
100000000
user=> (time (foo2 100000000))
"Elapsed time: 226.535655 msecs"
100000000

(defn foo2 [n]
  (let [n (int n)]
    (loop [i (int 0)]
      (if (< i n)
        (recur (inc i))
        :foo))))
#'user/foo2
user=> (time (foo2 100000000))
"Elapsed time: 57.383683 msecs"
:foo
user=> (time (foo2 100000000))
"Elapsed time: 56.647265 msecs"
:foo

(defn ^long foo2 [n]
  (let [n (int n)]
    (loop [i (int 0)]
      (if (< i n)
        (recur (inc i))
        i))))
#'user/foo2
user=> (time (foo2 100000000))
"Elapsed time: 51.049683 msecs"
100000000
user=> (time (foo2 100000000))
"Elapsed time: 47.310656 msecs"
100000000

@cgrand any idea why the first time it runs that boxing into object seems to be ignored? Is the var object somewhat ignoring the return type and then save the wrong info somewhere?

No clear idea. I believe it has something to do with on stack replacement, and later realizing that the replacement sig does not match the replacee sig 🤷 maybe even pushing some boxing inside the loop. Inspecting assembly could help figure out. But i definitely encountered this in the past.

More experiments: • explicit boxing on exit of the loop works great

user=>
(defn foo2 [n]
  (let [n (int n)]
    (loop [i (int 0)]
      (if (< i n)
        (recur (inc i))
        (Integer/valueOf i)))))
#'user/foo2
user=> (time (foo2 100000000))
"Elapsed time: 46.156153 msecs"
100000000
user=> (time (foo2 100000000))
"Elapsed time: 54.608185 msecs"
100000000

(defn foo2 [n]
  (let [n (int n)]
    (Integer/valueOf
      (loop [i (int 0)]
        (if (< i n)
          (recur (inc i))
          i)))))
#'user/foo2
user=> (time (foo2 100000000))
"Elapsed time: 45.705437 msecs"
100000000
user=> (time (foo2 100000000))
"Elapsed time: 220.503665 msecs"
100000000

However Long/valueOf instead of Integer/valueOf doesn’t work. Does it have to do with the size of the return type? I tried disabling UseCompressedOops but have seen no difference

On the plus side, I’m only able to reproduce on a plain REPL, it does not happen on a lein repl or from a main (meaning, prod apps are not affected)

On the minus side, I can:

$ clj -m foo2
"Elapsed time: 49.448754 msecs"
"Elapsed time: 240.798172 msecs"

where foo2.clj is

(ns foo2)

(defn foo2 [n]
  (let [n (int n)]
    (loop [i (int 0)]
      (if (< i n)
        (recur (inc i))
        i))))

(defn -main []
  (time (foo2 100000000))
  (time (foo2 100000000)))

Aot?

nope

also it’s tied to C2

$ clj -J-XX:TieredStopAtLevel=1 -m foo2
"Elapsed time: 85.075081 msecs"
"Elapsed time: 84.942798 msecs"
$ clj -J-XX:TieredStopAtLevel=4 -m foo2
"Elapsed time: 58.025492 msecs"
"Elapsed time: 222.761918 msecs"

@dominicm AOT:

$ java -cp classes:`clj -Spath` foo2
"Elapsed time: 57.144601 msecs"
"Elapsed time: 218.541054 msecs"

Ah. Maybe C2 is the difference here then.

Andy’s earlier post looked like it was doing osr in C3, then deopt in C3, then reopt in C4

Which matches cgrand’s hypothesis

C2 is what you call C4 (Tier 4), no? To me Tier 0 is interpreter, Tiers 1 to 3 are C1 with increasing profiling, Tier 4 is C2. We need a JDK specialist, @ghadi?

maybe so, dunno

Wow, thanks for all the investigation @cgrand. I will be trying to reproduce your cases and commentary in my repo for possible future reference.

Not sure if you were aware that Leiningen by default adds its own JVM command line options related to Tiered compilation, which make performance experiment results suspect, unless you override that by using something like the following in your project.clj file: :jvm-opts ^:replace ["jvm-opts-I-want"]

https://github.com/technomancy/leiningen/blob/87a6af9a12d5c479bfbb51f50b85c3fa4c2650a0/leiningen-core/src/leiningen/core/project.clj#L535-L539

OK, still no Twitter message to Aleksey Shipilev, and still no disassembly to JVM byte code nor Intel assembly code, but I have added brief instructions to the README, and attempted to automate what is there working across JDK8 through the latest versions (AdoptOpenJDK, OpenJDK, Azul Zulu, and Amazon Corretto all tested), and added Christophe's variations: https://github.com/jafingerhut/leeuwenhoek

My best guess is that we are seeing a case where some Clojure-compiled JVM byte codes are being optimized to faster machine code at JIT tier 3, vs. slower machine code when compiled at JIT tier 4, depending on exactly how you write that Clojure function.

Indeed! That’s now clear. It also reproduces on a pure java main, so there is “a problem” also in production code