Major Clojure 1.10 performance degredation on JDK11

[Elana Hashman]

On Tue, Feb 05, 2019 at 11:42:32PM -0600, Alex Miller wrote:
> 
> 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)

Is this a runtime or build arugment? I can't find this documented
anywhere except in this commit[0].

[0]: https://github.com/clojure/clojure/commit/3d9b356306db77946bdf4809baeb660f94cec846

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

So I think I found one fishy looking thing: while clojure.jar's
timestamps are all fine, it appears that the core.specs.alpha and
spec.alpha jars have .clj files with identical timestamps to the source
files, which may be affecting things. Ditto clojure1.8, etc. I believe
this is due to Debian's reproducible build steps.

However, that doesn't explain the massive slowdown between JDK8 and
JDK11 for all Clojure jars, 1.8 included.

elana at debian:/debian/clojure$ time /usr/lib/jvm/java-8-openjdk-amd64/bin/java -cp /usr/share/java/clojure-1.8.jar clojure.main -e '"hi"'
"hi"

real	0m4.368s
user	0m13.633s
sys	0m0.360s

elana at debian:/debian/clojure$ time /usr/lib/jvm/java-8-openjdk-amd64/bin/java -cp /usr/share/java/clojure-1.8.jar clojure.main -e '"hi"'
"hi"

real	0m3.941s
user	0m13.516s
sys	0m0.356s

elana at debian:/debian/clojure$ time /usr/lib/jvm/java-11-openjdk-amd64/bin/java -cp /usr/share/java/clojure-1.8.jar clojure.main -e '"hi"'
"hi"

real	0m9.962s
user	0m24.804s
sys	0m0.507s

elana at debian:/debian/clojure$ time /usr/lib/jvm/java-11-openjdk-amd64/bin/java -cp /usr/share/java/clojure-1.8.jar clojure.main -e '"hi"'
"hi"

real	0m10.040s
user	0m26.233s
sys	0m0.586s


I'm finding this utterly baffling.

For comparison, on the same machine I downloaded the official 1.8
release, and it's not seeing the same performance issues:

elana at debian:/tmp$ time /usr/lib/jvm/java-11-openjdk-amd64/bin/java -cp clojure-1.8.0.jar clojure.main -e '"hi"'
"hi"

real	0m1.377s
user	0m2.652s
sys	0m0.155s
elana at debian:/tmp$ time /usr/lib/jvm/java-8-openjdk-amd64/bin/java -cp clojure-1.8.0.jar clojure.main -e '"hi"'
"hi"

real	0m1.232s
user	0m2.048s
sys	0m0.124s


Another data point: clj 1.10 linked with the Debian core.specs.alpha and
spec.alpha:

elana at debian:/tmp$ time /usr/lib/jvm/java-8-openjdk-amd64/bin/java -cp clojure-1.10.0.jar:/usr/share/maven-repo/org/clojure/spec.alpha/debian/spec.alpha-debian.jar:/usr/share/maven-repo/org/clojure/core.specs.alpha/debian/core.specs.alpha-debian.jar clojure.main -e '"hi"'
"hi"

real	0m2.761s
user	0m7.836s
sys	0m0.317s
elana at debian:/tmp$ time /usr/lib/jvm/java-11-openjdk-amd64/bin/java -cp clojure-1.10.0.jar:/usr/share/maven-repo/org/clojure/spec.alpha/debian/spec.alpha-debian.jar:/usr/share/maven-repo/org/clojure/core.specs.alpha/debian/core.specs.alpha-debian.jar clojure.main -e '"hi"'
"hi"

real	0m4.363s
user	0m14.337s
sys	0m0.381s

vs. upstream specs, which it is faster with:

elana at debian:/tmp$ time /usr/lib/jvm/java-11-openjdk-amd64/bin/java -cp clojure-1.10.0.jar:core.specs.alpha-0.2.44.jar:spec.alpha-0.2.176.jar clojure.main -e '"hi"'
"hi"

real	0m1.688s
user	0m3.741s
sys	0m0.173s
elana at debian:/tmp$ time /usr/lib/jvm/java-8-openjdk-amd64/bin/java -cp clojure-1.10.0.jar:core.specs.alpha-0.2.44.jar:spec.alpha-0.2.176.jar clojure.main -e '"hi"'
"hi"

real	0m1.446s
user	0m2.752s
sys	0m0.166s


This strongly suggests to me that something different happening in the
Debian build process is causing a performance degradation.

Debian's up-to-date core.specs.alpha and spec.alpha are in the archive,
but in case anyone wants to poke around with the guts of the jars I
built/are installed in the archive[1].

Note that the terrible performance times I'm seeing here look similar to
what Rob reported when we had an issue with reproducible builds
affecting Clojure performance[2].

- e

[1]: https://csclub.uwaterloo.ca/~ehashman/debian/clojure/
[2]: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=877418
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: not available
URL: <http://alioth-lists.debian.net/pipermail/pkg-clojure-maintainers/attachments/20190207/a004e598/attachment.sig>