Major Clojure 1.10 performance degredation on JDK11

[Alex Miller]

We've had no reports of issues with Clojure 1.10 anywhere else (and really,
very little has changed that should affect startup time). I regularly run
Clojure 1.10 on Java 8-11 and have not noticed any significant differences.
The JVM itself did get a bit worse on 9, then better again on 10 and 11
(see
https://cl4es.github.io/2018/11/29/OpenJDK-Startup-From-8-Through-11.html),
but not of this magnitude.

Some things I would look at:

- Try with -Dclojure.spec.skip-macros=true to see if any difference (skips
spec macro checking which could possibly affect startup time)

- Check that you're actually using AOT'ed Clojure. In the clojure jar file,
typically you'll see both .class and .clj files. The timestamps matter! If
the .clj is newer than the .class files, it will use the .clj and
recompile. I have certainly seen people run into this kind of problem with
builds that don't retain timestamps properly for whatever reason (the Maven
shade plugin is a notorious culprit, but we don't use that in the Clojure
build).

In general, I'd say *all* of these times look super slow to me - I would
expect in the ballpark of 1s. I'm also curious what is in those jars - do
they include the spec libs too? If so, that seems weird to me.

On my new-ish macbook pro (my 5 yo MBP is not much slower):

#### Java 11 (build 11+28), Clojure 1.10

$ time java -cp
/Users/alex/.m2/repository/org/clojure/clojure/1.10.0/clojure-1.10.0.jar:/Users/alex/.m2/repository/org/clojure/spec.alpha/0.2.176/spec.alpha-0.2.176.jar:/Users/alex/.m2/repository/org/clojure/core.specs.alpha/0.2.44/core.specs.alpha-0.2.44.jar
clojure.main -e '"hi"'
"hi"

real 0m0.758s
user 0m1.217s
sys 0m0.089s

#### Java 8 (build 1.8.0_181-b13), Clojure 1.10

$ time java -cp
/Users/alex/.m2/repository/org/clojure/clojure/1.10.0/clojure-1.10.0.jar:/Users/alex/.m2/repository/org/clojure/spec.alpha/0.2.176/spec.alpha-0.2.176.jar:/Users/alex/.m2/repository/org/clojure/core.specs.alpha/0.2.44/core.specs.alpha-0.2.44.jar
clojure.main -e '"hi"'
"hi"

real 0m0.760s
user 0m1.310s
sys 0m0.090s

#### Java 11 (build 11+28), Clojure 1.9

$ time java -cp
/Users/alex/.m2/repository/org/clojure/clojure/1.9.0/clojure-1.9.0.jar:/Users/alex/.m2/repository/org/clojure/spec.alpha/0.1.143/spec.alpha-0.1.143.jar:/Users/alex/.m2/repository/org/clojure/core.specs.alpha/0.1.24/core.specs.alpha-0.1.24.jar
clojure.main -e '"hi"'
"hi"

real 0m0.828s
user 0m1.301s
sys 0m0.086s

#### Java 8 (build 1.8.0_181-b13), Clojure 1.9

$ time java -cp
/Users/alex/.m2/repository/org/clojure/clojure/1.9.0/clojure-1.9.0.jar:/Users/alex/.m2/repository/org/clojure/spec.alpha/0.1.143/spec.alpha-0.1.143.jar:/Users/alex/.m2/repository/org/clojure/core.specs.alpha/0.1.24/core.specs.alpha-0.1.24.jar
clojure.main -e '"hi"'
"hi"

real 0m0.761s
user 0m1.297s
sys 0m0.087s

#### Java 11 (build 11+28), Clojure 1.8

$ time java -cp
/Users/alex/.m2/repository/org/clojure/clojure/1.8.0/clojure-1.8.0.jar
clojure.main -e '"hi"'
"hi"

real 0m0.705s
user 0m1.220s
sys 0m0.091s

#### Java 8 (build 1.8.0_181-b13), Clojure 1.8

$ time java -cp
/Users/alex/.m2/repository/org/clojure/clojure/1.8.0/clojure-1.8.0.jar
clojure.main -e '"hi"'
"hi"

real 0m0.623s
user 0m1.001s
sys 0m0.076s


On Tue, Feb 5, 2019 at 10:54 PM Elana Hashman <ehashman at debian.org> wrote:

> Hi Alex (+cc team),
>
> I'm working on upgrading Clojure 1.9 in Debian to Clojure 1.10.
>
> I noticed when running my very brief autopkgtest suite that the tests
> were unusually slow. Sure enough, I seem to have hit some sort of
> startup time degradation. Here's some tests run with various JDKs:
>
> elana at debian:/debian$ time /usr/lib/jvm/java-8-openjdk-amd64/bin/java -cp
> /usr/share/java/clojure-1.10.jar clojure.main -e '"hi"'
> "hi"
>
> real    0m5.032s
> user    0m18.415s
> sys     0m0.529s
> elana at debian:/debian$ time /usr/lib/jvm/java-9-openjdk-amd64/bin/java -cp
> /usr/share/java/clojure-1.10.jar clojure.main -e '"hi"'
> "hi"
>
> real    0m6.674s
> user    0m22.503s
> sys     0m0.631s
> elana at debian:/debian$ time /usr/lib/jvm/java-10-openjdk-amd64/bin/java
> -cp /usr/share/java/clojure-1.10.jar clojure.main -e '"hi"'
> "hi"
>
> real    0m6.231s
> user    0m20.863s
> sys     0m0.604s
> elana at debian:/debian$ time /usr/lib/jvm/java-11-openjdk-amd64/bin/java
> -cp /usr/share/java/clojure-1.10.jar clojure.main -e '"hi"'
> "hi"
>
> real    0m13.794s
> user    0m34.169s
> sys     0m0.695s
>
> It's also substantially slower than 1.8 and 1.9 on JDK11:
>
> elana at debian:/debian$ time clojure1.9 -e '"hi"'  # alias for the command
> line above
> "hi"
>
> real    0m9.996s
> user    0m23.960s
> sys     0m0.577s
> elana at debian:/debian$ time clojure1.8 -e '"hi"'
> "hi"
>
> real    0m9.941s
> user    0m24.713s
> sys     0m0.618s
>
> Debian Buster isn't going to ship with JDK8, unfortunately, so I'm
> hoping we can figure out the source of the issue in order to get 1.10
> into the release. I just discovered the performance regression on my
> latest build so I haven't had much time to dig into root causes, but I
> wondered if you were aware of any performance issues with Clojure 1.10
> on JDK11.
>
> Throwing some possible things out there: more weirdness from
> reproducible builds (I don't think Clojure is reproducible yet anyways),
> bytecode recompilation due to mismatch (would be weird, I'm building it
> with JDK11), ...
>
> I think it would also be good to check 1.8 and 1.9 on JDKs 8-10 to
> compare results (but I haven't had the chance to do so).
>
> Cheers,
>
> - e
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://alioth-lists.debian.net/pipermail/pkg-clojure-maintainers/attachments/20190205/f9ec1442/attachment.html>