graal
graal copied to clipboard
oracle
Unexpected runtime exception with GraalVM EE 22.2
Describe the issue After upgrading to 22.2 the GraalVM EE starts to throw unexpected runtime exception during warming up of some benchmark.
Steps to reproduce the issue
1. git clone --depth 1 https://github.com/plokhotnyuk/jsoniter-scala
2. sbt -java-home /usr/lib/jvm/graalvm-ee-java17 clean 'jsoniter-scala-benchmarkJVM/jmh:run -p size=128 ArrayOfEnumADTsReading.dslJsonScala'
Describe GraalVM and your environment:
- GraalVM version: EE 22.2
- JDK major version: 11/17 (both versions are affected)
- OS: Ubuntu 22.04
- Architecture: AMD64
More details Bellow is a part of the benchmark log with used JVM options and a stack trace sample:
[info] # JMH version: 1.35
[info] # VM version: JDK 17.0.4, Java HotSpot(TM) 64-Bit Server VM, 17.0.4+11-LTS-jvmci-22.2-b05
[info] # VM invoker: /usr/lib/jvm/graalvm-ee-java17/bin/java
[info] # VM options: -server -Xms2g -Xmx2g -XX:NewSize=1g -XX:MaxNewSize=1g -XX:InitialCodeCacheSize=512m -XX:ReservedCodeCacheSize=512m -XX:+UseParallelGC -XX:-UseAdaptiveSizePolicy -XX:MaxInlineLevel=18 -XX:+AlwaysPreTouch -XX:+UseNUMA -XX:-UseAdaptiveNUMAChunkSizing
[info] # Blackhole mode: compiler (auto-detected, use -Djmh.blackhole.autoDetect=false to disable)
[info] # Warmup: 5 iterations, 1 s each
[info] # Measurement: 5 iterations, 1 s each
[info] # Timeout: 10 min per iteration
[info] # Threads: 1 thread, will synchronize iterations
[info] # Benchmark mode: Throughput, ops/time
[info] # Benchmark: com.github.plokhotnyuk.jsoniter_scala.benchmark.ArrayOfEnumADTsReading.dslJsonScala
[info] # Parameters: (size = 128)
[info] # Run progress: 0.00% complete, ETA 00:00:10
[info] # Fork: 1 of 1
[info] # Warmup Iteration 1: 288121.440 ops/s
[info] # Warmup Iteration 2: <failure>
[info] com.dslplatform.json.ParsingException: Invalid value: 'Spades' for interface com.github.plokhotnyuk.jsoniter_scala.benchmark.SuitADT. Found " at position: 9, following: `["Spades"`, before: `,"Diamonds","Clubs",`
[info] at com.dslplatform.json.ParsingException.create(ParsingException.java:16)
[info] at com.dslplatform.json.JsonReader.newParseError(JsonReader.java:420)
[info] at com.dslplatform.json.JsonReader.newParseError(JsonReader.java:408)
[info] at com.dslplatform.json.runtime.ScalaEnumAsTraitAnalyzer$ScalaTraitDescription.read(ScalaEnumAsTraitAnalyzer.scala:78)
[info] at com.dslplatform.json.runtime.ArrayDecoder.read(ArrayDecoder.java:30)
[info] at com.dslplatform.json.runtime.ArrayDecoder.read(ArrayDecoder.java:9)
[info] at com.github.plokhotnyuk.jsoniter_scala.benchmark.DslPlatformJson$.dslJsonDecode(DslPlatformJson.scala:121)
[info] at com.github.plokhotnyuk.jsoniter_scala.benchmark.ArrayOfEnumADTsReading.dslJsonScala(ArrayOfEnumADTsReading.scala:54)
[info] at com.github.plokhotnyuk.jsoniter_scala.benchmark.jmh_generated.ArrayOfEnumADTsReading_dslJsonScala_jmhTest.dslJsonScala_thrpt_jmhStub(ArrayOfEnumADTsReading_dslJsonScala_jmhTest.java:119)
[info] at com.github.plokhotnyuk.jsoniter_scala.benchmark.jmh_generated.ArrayOfEnumADTsReading_dslJsonScala_jmhTest.dslJsonScala_Throughput(ArrayOfEnumADTsReading_dslJsonScala_jmhTest.java:83)
[info] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[info] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[info] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[info] at java.base/java.lang.reflect.Method.invoke(Method.java:568)
[info] at org.openjdk.jmh.runner.BenchmarkHandler$BenchmarkTask.call(BenchmarkHandler.java:475)
[info] at org.openjdk.jmh.runner.BenchmarkHandler$BenchmarkTask.call(BenchmarkHandler.java:458)
[info] at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[info] at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
[info] at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[info] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
[info] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[info] at java.base/java.lang.Thread.run(Thread.java:833)
It is possible to run something after sbt -java-home /usr/lib/jvm/graalvm-ee-java17 clean 'jsoniter-scala-benchmarkJVM/jmh:run -p size=128 ArrayOfEnumADTsReading.dslJsonScala' to reproduce the crash without doing a bunch of Java and Scala compilation? That is, is there a java command line for running the generated jar(s):
> ls -1 jsoniter-scala-benchmark/jvm/target/scala-2.13/jsoniter-scala-benchmark_2.13-2.13.40-SNAPSHOT*
jsoniter-scala-benchmark/jvm/target/scala-2.13/jsoniter-scala-benchmark_2.13-2.13.40-SNAPSHOT.jar
jsoniter-scala-benchmark/jvm/target/scala-2.13/jsoniter-scala-benchmark_2.13-2.13.40-SNAPSHOT-jmh.jar
jsoniter-scala-benchmark/jvm/target/scala-2.13/jsoniter-scala-benchmark_2.13-2.13.40-SNAPSHOT-tests.jar
This will allow me to more easily play around with different VM options.
If I try to reduce sbt execution time by omitting the clean step, I get:
[info] welcome to sbt 1.7.1 (Oracle Corporation Java 17.0.4)
[info] loading settings for project jsoniter-scala-build from plugins.sbt ...
[info] loading project definition from /home/dnsimon/jsoniter-scala/project
[info] loading settings for project jsoniter-scala from build.sbt,release.sbt,version.sbt ...
[info] resolving key references (10981 settings) ...
[info] set current project to jsoniter-scala (in build file:/home/dnsimon/jsoniter-scala/)
[warn] sbt 0.13 shell syntax is deprecated; use slash syntax instead: jsoniter-scala-benchmarkJVM / Jmh / run
[info] compiling 2004 Java sources to /home/dnsimon/jsoniter-scala/jsoniter-scala-benchmark/jvm/target/scala-2.13/classes ...
[info] done compiling
[error] java.io.FileNotFoundException: /home/dnsimon/jsoniter-scala/jsoniter-scala-benchmark/jvm/target/scala-2.13/classes/com/github/plokhotnyuk/jsoniter_scala/benchmark/jmh_generated/ADTReading_avSystemGenCodec_jmhTest.class (No such file or directory)
[error] at java.base/java.io.FileInputStream.open0(Native Method)
[error] at java.base/java.io.FileInputStream.open(FileInputStream.java:216)
[error] at java.base/java.io.FileInputStream.<init>(FileInputStream.java:157)
[error] at sbt.io.Using$.$anonfun$fileInputStream$1(Using.scala:98)
[error] at sbt.io.Using$$anon$3.openImpl(Using.scala:86)
[error] at sbt.io.OpenFile.open(Using.scala:53)
[error] at sbt.io.OpenFile.open$(Using.scala:47)
[error] at sbt.io.Using$$anon$3.open(Using.scala:85)
[error] at sbt.io.Using$$anon$3.open(Using.scala:85)
[error] at sbt.io.Using.apply(Using.scala:25)
[error] at sbt.io.IO$.transfer(IO.scala:448)
[error] at sbt.io.IO$.addFileEntry$1(IO.scala:710)
[error] at sbt.io.IO$.$anonfun$writeZip$6(IO.scala:718)
[error] at sbt.io.IO$.$anonfun$writeZip$6$adapted(IO.scala:718)
[error] at scala.collection.immutable.List.foreach(List.scala:431)
[error] at sbt.io.IO$.writeZip(IO.scala:718)
[error] at sbt.io.IO$.$anonfun$archive$2(IO.scala:668)
[error] at sbt.io.IO$.$anonfun$archive$2$adapted(IO.scala:665)
[error] at sbt.io.IO$.$anonfun$withZipOutput$1(IO.scala:765)
[error] at sbt.io.IO$.$anonfun$withZipOutput$1$adapted(IO.scala:745)
[error] at sbt.io.Using.apply(Using.scala:27)
[error] at sbt.io.IO$.withZipOutput(IO.scala:745)
[error] at sbt.io.IO$.archive(IO.scala:665)
[error] at sbt.io.IO$.jar(IO.scala:630)
[error] at sbt.Package$.makeJar(Package.scala:228)
[error] at sbt.Package$.$anonfun$apply$4(Package.scala:151)
[error] at sbt.Package$.$anonfun$apply$4$adapted(Package.scala:149)
[error] at sbt.util.Tracked$.$anonfun$outputChangedW$1(Tracked.scala:128)
[error] at sbt.Package$.apply(Package.scala:161)
[error] at sbt.Defaults$.$anonfun$packageTask$1(Defaults.scala:1861)
[error] at scala.Function1.$anonfun$compose$1(Function1.scala:49)
[error] at sbt.internal.util.$tilde$greater.$anonfun$$u2219$1(TypeFunctions.scala:62)
[error] at sbt.std.Transform$$anon$4.work(Transform.scala:68)
[error] at sbt.Execute.$anonfun$submit$2(Execute.scala:282)
[error] at sbt.internal.util.ErrorHandling$.wideConvert(ErrorHandling.scala:23)
[error] at sbt.Execute.work(Execute.scala:291)
[error] at sbt.Execute.$anonfun$submit$1(Execute.scala:282)
[error] at sbt.ConcurrentRestrictions$$anon$4.$anonfun$submitValid$1(ConcurrentRestrictions.scala:265)
[error] at sbt.CompletionService$$anon$2.call(CompletionService.scala:64)
[error] at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[error] at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
[error] at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[error] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
[error] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[error] at java.base/java.lang.Thread.run(Thread.java:833)
[error] (jsoniter-scala-benchmarkJVM / Compile / packageBin) java.io.FileNotFoundException: /home/dnsimon/jsoniter-scala/jsoniter-scala-benchmark/jvm/target/scala-2.13/classes/com/github/plokhotnyuk/jsoniter_scala/benchmark/jmh_generated/ADTReading_avSystemGenCodec_jmhTest.class (No such file or directory)
even though /home/dnsimon/jsoniter-scala/jsoniter-scala-benchmark/jvm/target/scala-2.13/classes/com/github/plokhotnyuk/jsoniter_scala/benchmark/jmh_generated/ADTReading_avSystemGenCodec_jmhTest.class exists.
[error] (jsoniter-scala-benchmarkJVM / Compile / packageBin) java.io.FileNotFoundException: /home/dnsimon/jsoniter-scala/jsoniter-scala-benchmark/jvm/target/scala-2.13/classes/com/github/plokhotnyuk/jsoniter_scala/benchmark/jmh_generated/ADTReading_avSystemGenCodec_jmhTest.class (No such file or directory)
even though `/home/dnsimon/jsoniter-scala/jsoniter-scala-benchmark/jvm/target/scala-2.13/classes/com/github/plokhotnyuk/jsoniter_scala/benchmark/jmh_generated/ADTReading_avSystemGenCodec_jmhTest.class` exists.
That is why clean is used.
I'm going to modify source in a branch to build a bundle jar that can be started with java -jar <path-to-bundle>/jsoniter-scala-benchmark-assembly-2.13.40-SNAPSHOT.jar.
New steps to reproduce with running an uber jar:
git clone --depth 1 https://github.com/plokhotnyuk/jsoniter-scala
cd jsoniter-scala
git checkout github.com/oracle/graal/issues/4773
sbt clean 'jsoniter-scala-benchmarkJVM/jmh:run ADTReading.jsoniter -i 1 -wi 1' jsoniter-scala-benchmarkJVM/assembly
/usr/lib/jvm/graalvm-ee-java17/bin/java -jar jsoniter-scala-benchmark/jvm/target/scala-2.13/jsoniter-scala-benchmark-assembly-2.13.40-SNAPSHOT.jar ArrayOfEnumADTsReading.dslJsonScala
Thanks @plokhotnyuk . It seems like this is not a Graal compiler problem since adding -XX:-UseJVMCICompiler does not prevent the crash. However, it still seems related to GraalVM as it does not crash on labsjdk or OracleJDK.
The benchmark is a simple single-thread test where no concurrency is involved except class loading and other JVM stuff that can run concurrently. Could it be due the tested JSON parser generates and then run byte-code on the first call of the benchmark method?
Also, it works fine with CE edition for me. Have GraalVM EE some difference with CE beside the JVMCI compiler?
Yes, there must be some difference but I haven't found it yet. The problem reproduces on EE even with -Xint (i.e. no compilation at all).
After reducing the iteration time to 100ms in a subsequent commit of the issue branch I see that the exception occurs after ~0.5s of successful benchmark running:
andriy@notebook:~/Projects/com/github/plokhotnyuk/jsoniter-scala$ /usr/lib/jvm/graalvm-ee-java17/bin/java -jar /home/andriy/Projects/com/github/plokhotnyuk/jsoniter-scala/jsoniter-scala-benchmark/jvm/target/scala-2.13/jsoniter-scala-benchmark-assembly-2.13.40-SNAPSHOT.jar ArrayOfEnumADTsReading.dslJsonScala
# JMH version: 1.35
# VM version: JDK 17.0.4, Java HotSpot(TM) 64-Bit Server VM, 17.0.4+11-LTS-jvmci-22.2-b05
# VM invoker: /usr/lib/jvm/graalvm-ee-java17/bin/java
# VM options: -server -Xms2g -Xmx2g -XX:NewSize=1g -XX:MaxNewSize=1g -XX:InitialCodeCacheSize=512m -XX:ReservedCodeCacheSize=512m -XX:+UseParallelGC -XX:-UseAdaptiveSizePolicy -XX:MaxInlineLevel=18 -XX:+AlwaysPreTouch -XX:+UseNUMA -XX:-UseAdaptiveNUMAChunkSizing
# Blackhole mode: compiler (auto-detected, use -Djmh.blackhole.autoDetect=false to disable)
# Warmup: 50 iterations, 100 ms each
# Measurement: 50 iterations, 100 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: com.github.plokhotnyuk.jsoniter_scala.benchmark.ArrayOfEnumADTsReading.dslJsonScala
# Parameters: (size = 128)
# Run progress: 0.00% complete, ETA 00:00:10
# Fork: 1 of 1
# Warmup Iteration 1: 1.669 ops/s
# Warmup Iteration 2: 550792.133 ops/s
# Warmup Iteration 3: 764567.139 ops/s
# Warmup Iteration 4: 776669.919 ops/s
# Warmup Iteration 5: 764874.375 ops/s
# Warmup Iteration 6: 781909.705 ops/s
# Warmup Iteration 7: <failure>
com.dslplatform.json.ParsingException: Invalid value: 'Spades' for interface com.github.plokhotnyuk.jsoniter_scala.benchmark.SuitADT. Found " at position: 9, following: `["Spades"`, before: `,"Diamonds","Clubs",`
at com.dslplatform.json.ParsingException.create(ParsingException.java:16)
at com.dslplatform.json.JsonReader.newParseError(JsonReader.java:420)
at com.dslplatform.json.JsonReader.newParseError(JsonReader.java:408)
...
BTW, I have found that adding -Xint between java and -jar doesn't switch to byte code interpreter only mode and the benchmark shows throughput the same as compiled with the full optimization. Probably those options are not taken in account in the internal fork of the JMH library.
You can add JVM option to the Fork annotation parameter list that is defined in the CommonParams class of benchmarks, but it will require recompilation.
In an additional commit I have added passing of program parameters as JVM options for the forked benchmark and now -Xint parameter switches to the interpreter only mode:
andriy@notebook:~/Projects/com/github/plokhotnyuk/jsoniter-scala$ /usr/lib/jvm/graalvm-ee-java17/bin/java -cp /home/andriy/Projects/com/github/plokhotnyuk/jsoniter-scala/jsoniter-scala-benchmark/jvm/target/scala-2.13/jsoniter-scala-benchmark-assembly-2.13.40-SNAPSHOT.jar com.github.plokhotnyuk.jsoniter_scala.benchmark.Main -Xint
# JMH version: 1.35
# VM version: JDK 17.0.4, Java HotSpot(TM) 64-Bit Server VM, 17.0.4+11-LTS-jvmci-22.2-b05
# VM invoker: /usr/lib/jvm/graalvm-ee-java17/bin/java
# VM options: -Xint
# Blackhole mode: compiler (auto-detected, use -Djmh.blackhole.autoDetect=false to disable)
# Warmup: 50 iterations, 100 ms each
# Measurement: 50 iterations, 100 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: com.github.plokhotnyuk.jsoniter_scala.benchmark.ArrayOfEnumADTsReading.dslJsonScala
# Parameters: (size = 128)
# Run progress: 0.00% complete, ETA 00:00:10
# Fork: 1 of 1
# Warmup Iteration 1: 0.596 ops/s
# Warmup Iteration 2: 13842.477 ops/s
# Warmup Iteration 3: 13875.773 ops/s
# Warmup Iteration 4: 14087.814 ops/s
# Warmup Iteration 5: 14101.699 ops/s
# Warmup Iteration 6: 14100.085 ops/s
# Warmup Iteration 7: 14083.604 ops/s
# Warmup Iteration 8: 14093.016 ops/s
Also, switching to non-Graal compiler doesn't reproduce the exception:
andriy@notebook:~/Projects/com/github/plokhotnyuk/jsoniter-scala$ /usr/lib/jvm/graalvm-ee-java17/bin/java -cp /home/andriy/Projects/com/github/plokhotnyuk/jsoniter-scala/jsoniter-scala-benchmark/jvm/target/scala-2.13/jsoniter-scala-benchmark-assembly-2.13.40-SNAPSHOT.jar com.github.plokhotnyuk.jsoniter_scala.benchmark.Main -XX:-UseJVMCICompiler
# JMH version: 1.35
# VM version: JDK 17.0.4, Java HotSpot(TM) 64-Bit Server VM, 17.0.4+11-LTS-jvmci-22.2-b05
# VM invoker: /usr/lib/jvm/graalvm-ee-java17/bin/java
# VM options: -XX:-UseJVMCICompiler
# Blackhole mode: compiler (auto-detected, use -Djmh.blackhole.autoDetect=false to disable)
# Warmup: 50 iterations, 100 ms each
# Measurement: 50 iterations, 100 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: com.github.plokhotnyuk.jsoniter_scala.benchmark.ArrayOfEnumADTsReading.dslJsonScala
# Parameters: (size = 128)
# Run progress: 0.00% complete, ETA 00:00:10
# Fork: 1 of 1
# Warmup Iteration 1: 1.710 ops/s
# Warmup Iteration 2: 250215.528 ops/s
# Warmup Iteration 3: 563383.039 ops/s
# Warmup Iteration 4: 466499.607 ops/s
# Warmup Iteration 5: 651919.638 ops/s
# Warmup Iteration 6: 651635.341 ops/s
# Warmup Iteration 7: 654093.275 ops/s
# Warmup Iteration 8: 658845.293 ops/s
# Warmup Iteration 9: 652678.646 ops/s
# Warmup Iteration 10: 648704.092 ops/s
# Warmup Iteration 11: 655234.281 ops/s
New steps to reproduce with switchable JVM options are:
git clone --depth 1 https://github.com/plokhotnyuk/jsoniter-scala
cd jsoniter-scala
git checkout github.com/oracle/graal/issues/4773
sbt clean 'jsoniter-scala-benchmarkJVM/jmh:run ADTReading.jsoniter -i 1 -wi 1' jsoniter-scala-benchmarkJVM/assembly
/usr/lib/jvm/graalvm-ee-java17/bin/java -cp jsoniter-scala-benchmark/jvm/target/scala-2.13/jsoniter-scala-benchmark-assembly-2.13.40-SNAPSHOT.jar com.github.plokhotnyuk.jsoniter_scala.benchmark.Main <list of JVM options separated by whitespaces>
Ok, thanks. Now it makes more sense and likely does indicate a Graal EE compiler bug after all.
A workaround to avoid the exception is using -Dgraal.LoopPeeling=false.
Would it be helpful for finding the root cause?
@plokhotnyuk thanks for your efforts, sadly optimizations are just "enablers" for this particular bug. I could narrow it down to an invalid integer stamp based optimization that is itself tiny but has breaking impact for this application. We are computing a wrong stamp that leads to empty stamps at usage nodes effectively dropping a loop phi. The problem as well as the fix are not trivial. I will post here once we deployed a fix (working on it).
