pshipton
commented
2 years ago @tajila
Open Sidong-Wei opened 2 years ago
pshipton
commented
2 years ago @tajila
tajila
commented
2 years ago @ChengJin01 Please take a look at this
ChengJin01
commented
2 years ago Just talked to @Sidong-Wei offline. The reason why the VerifyError was captured during runtime verification (which is correct as AbstractIndex is not throwable) is that the Scala scource was already mistakenly compiled to the wrong bytecode on s390x by the Gradle compiler, which is out of VM scope given the bytecode is statically generated in the .jar file before running the bytecode.
@Sidong-Wei might need to investigate why the bytecode wasn't compiled correctly as expected on s390x. e.g. whether there is any connection to the java compiler (javac) or something else specific to s390x.
Sidong-Wei
commented
2 years ago Hi @ChengJin01 thanks a lot for your input, I think you made a good point in claiming the issue has nothing to do with the Verifier or JVM as the issue happens bytecode was compiled statically. I further looked into how the Kafka project use java compiler and scala compiler to compile its source code.
I found that it is using the gradle scala plugin, which use the zinc compiler to compile its hybrid java and scala code. I checked the source code of the compiler and tested with different JDKs, and I did not find any evidence that it has platform specific code or jvm specific code, which leads to the assumption that the issue I experienced may be still within the JDK scope (based on different bytecode on same machine with different JDK).
I understand the difference between Openj9 and Hotspot is mainly on the JVM side, but I believe there is still difference between these variants in terms of libraries and javac implementation. (i.e. I remember the ThreadMXBean.getThreadAllocatedBytes method from com.sun.management package is implemented in Hotspot but not in Openj9), so I wonder if there is someone in the openj9 community who coule help with this type of issue (with javac or shared library)? Since the issue is both platform-relevant and JDK-relevant, I suspect the issue may be with the specific javac implementation on s390x in openj9 repo, and any help to further narrow the issue down would be greatly appreciated, thanks.
ChengJin01
commented
2 years ago @Sidong-Wei, the java compiler (javac) is implemented in OpenJDK which doesn't belong to OpenJ9.
The question is whether the zinc compiler depends on javac to do compilation. Even so, I still doubt the issue was triggered by javac. So it is likely there is intermediate source code generated by zinc prior to the bytecode, which is different across platforms.
ChengJin01
commented
2 years ago I double-checked this project at https://github.com/apache/kafka/tree/3.0 and noticed that the kafka/core/src/main/scala/kafka/log/AbstractIndex.scala was compiled to kafka/core/build/classes/scala/main/kafka/log/AbstractIndex.class with the command ./gradlew core:compileScala wich launched at least 3 java processes during the building progress as follows:
[1] The background GradleDaemon: jdk11_openj9_semeru/bin/java -Xss4m -XX:+UseParallelGC --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.base/java.lang=ALL-UNNAMED --add-opens java.base/java.lang.invoke=ALL-UNNAMED --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.prefs/java.util.prefs=ALL-UNNAMED --add-opens java.prefs/java.util.prefs=ALL-UNNAMED --add-opens java.base/java.nio.charset=ALL-UNNAMED --add-opens java.base/java.net=ALL-UNNAMED --add-opens java.base/java.util.concurrent.atomic=ALL-UNNAMED -Xmx2g -Dfile.encoding=UTF-8 -Duser.country=US -Duser.language=en -Duser.variant -cp /home/jenkins/.gradle/wrapper/dists/gradle-7.1.1-all/1wqbeia0d49252rmlcr6o8lbl/gradle-7.1.1/lib/gradle-launcher-7.1.1.jar org.gradle.launcher.daemon.bootstrap.GradleDaemon 7.1.1
[2] The GradleWrapperMain (command line parser): jdk11_openj9_semeru/bin/java -Xint -Xmx64m -Xms64m -Dorg.gradle.appname=gradlew -classpath /home/jenkins/jchau_ffi/14054_apache_kafka_jdk11/kafka/gradle/wrapper/gradle-wrapper.jar org.gradle.wrapper.GradleWrapperMain core:compileScala
[3] The Gradle Worker Daemon: e.g. jdk11_openj9_semeru/bin/java -Xss4m -XX:+UseParallelGC @/home/jenkins/.gradle/.tmp/gradle-worker-classpath2336945854620526368txt -Xmx2048m -Dfile.encoding=UTF-8 -Duser.country=US -Duser.language=en -Duser.variant worker.org.gradle.process.internal.worker.GradleWorkerMain 'Gradle Worker Daemon 1'
By modifying kafka/build.gradle to disable JIT on The Gradle Worker Daemon as follows:
defaultJvmArgs = ["-Xint", "-Xss4m", "-XX:+UseParallelGC"]the issue disappeared (tried many times) and ended up with the correct bytecode:
public kafka.log.AbstractIndex(java.io.File, long, int, boolean);
descriptor: (Ljava/io/File;JIZ)V
flags: (0x0001) ACC_PUBLIC
Code:
stack=7, locals=13, args_size=5
...
244: aload 8
246: goto 277
249: astore 9 <----- push the thrown vlaue to the local variable #9
251: getstatic #238 // Field kafka/utils/CoreUtils$.MODULE$:Lkafka/utils/CoreUtils$;
254: aload 7
256: invokedynamic #643, 0 // InvokeDynamic #1:apply$mcV$sp:(Ljava/io/RandomAccessFile;)Lscala/runtime/java8/JFunction0$mcV$sp;
261: getstatic #51 // Field kafka/log/AbstractIndex$.MODULE$:Lkafka/log/AbstractIndex$;
264: getstatic #238 // Field kafka/utils/CoreUtils$.MODULE$:Lkafka/utils/CoreUtils$;
267: pop
268: getstatic #590 // Field org/slf4j/event/Level.WARN:Lorg/slf4j/event/Level;
271: invokevirtual #594 // Method kafka/utils/CoreUtils$.swallow:(Lscala/Function0;Lkafka/utils/Logging;Lorg/slf4j/event/Level;)V
274: aload 9 <----- load the thrown vlaue from the local variable #9
276: athrow
...
Exception table:
from to target type
85 249 249 anyMy understanding is that the scala source must be loaded/compiled directly to bytecode in memory and was most likely optimized in there by JIT before being outputted into the class file but still unclear where the optimization occurred.
So we need to get the JIT team involved in the investigation to see how & why this happened in this case.
FYI: @0xdaryl
DanHeidinga
commented
2 years ago @0xdaryl can you update this for the 0.30 release?
0xdaryl
commented
2 years ago JIT hasn't had a chance to look at the failure yet. Thanks @Sidong-Wei for your thorough investigation upon opening the PR. Given the apparent Z-specific nature of the problem, I'll ask @joransiu to assign for JIT investigation based on @ChengJin01's helpful analysis so far.
This seems unlikely to be resolved for 0.30.
pshipton
commented
2 years ago I'll move it out.
jonathan-albrecht-ibm
commented
2 years ago I'm wondering if I could get an update on where this issue stands? Is there a plan to implement it in a particular release? I retested this against the current kafka 3.2.0 source release and this issue still occurs. I tested with the IBM Semeru Runtime Certified Edition 11.0.15.0 (build 11.0.15+10)
pshipton
commented
2 years ago @joransiu it seems the question is for you.
joransiu
commented
2 years ago Apologies for the delay. I missed the original tag, so unfortuantely, no updates to report. Will have someone look into this from JIT perspective.
VermaSh
commented
2 years ago Hey, @Sidong-Wei I am going to be looking in to this failure. What commands did you use to setup and run? Is this it?
curl -kn0OL https://archive.apache.org/dist/kafka/3.0.0/kafka-3.0.0-src.tgz
tar -xf kafka-3.0.0-src.tgz
cd kafka-3.0.0-src/
bin/zookeeper-server-start.sh config/zookeeper.properties
# In a separate console
bin/kafka-server-start.sh config/server.propertiesHi @VermaSh I can help you with this issue. You can reproduce it from the unit tests which may be easier.
It's actually easier to setup with kafka 3.2.0 now which has better support for s390x in the jar dependencies.
mkdir src
curl -kn0OL https://archive.apache.org/dist/kafka/3.2.0/kafka-3.2.0-src.tgz
cd src/
tar xf ../kafka-3.2.0-src.tgz
cd kafka-3.2.0-src/
# I'm using IBM Semeru Runtime Certified Edition 11.0.15.0 (build 11.0.15+10)
export JAVA_HOME=/opt/jdk-11.0.15+10
./gradlew jar
# At this point you should be able to run through the quickstart guide but I haven't tried it.
# Several of the tests in the core module will fail. This is one of them:
./gradlew :core:test --tests FetchRequestBetweenDifferentIbpTest.testControllerOldToNewIBPyou should see an error that starts with:
FetchRequestBetweenDifferentIbpTest > testControllerOldToNewIBP() FAILED java.lang.VerifyError: JVMVRFY021 thrown object not throwable; class=kafka/log/AbstractIndex, method=<init>(Ljava/io/File;JIZ)V, pc=274 Exception Details: Location:
kafka/log/AbstractIndex.<init>(Ljava/io/File;JIZ)V @274: JBathrow
Reason:
Type 'kafka/log/AbstractIndex' (current frame, stack[0]) is not assignable to 'java/lang/Throwable'
Current Frame:
bci: @274
flags: { }
locals: { 'kafka/log/AbstractIndex', 'java/io/File', long, long_2nd, integer, integer, integer, 'java/io/RandomAccessFile' }
stack: { 'kafka/log/AbstractIndex' }
Exception Handler Table:
bci [85, 249] => handler: 249
Stackmap Table:
...Let me know if I can help
jonathan-albrecht-ibm
commented
1 year ago Hi @VermaSh, just wondering if there is any update on this issue?
VermaSh
commented
1 year ago Hi @jonathan-albrecht-ibm, Sorry I got swamped with some other work so don't have an update right now. But I'll try to have an update over next few days.
VermaSh
commented
1 year ago Quick update: Disabling asynchronous JIT compilation for gradle worker daemon fixes the failures. Doing a binary search now to get the failing JIT method.
jonathan-albrecht-ibm
commented
1 year ago Hi @VermaSh, just wanted to check if you were able to find the failing JIT method.
VermaSh
commented
1 year ago Hey @jonathan-albrecht-ibm It fails when scala/tools/asm/tree/analysis/Analyzer.analyze(Ljava/lang/String;Lscala/tools/asm/tree/MethodNode;)[Lscala/tools/asm/tree/analysis/Frame; is compiled at opt level hot. Limiting the method to opt level warm or below results in correct byte being generated for AbstractIndex : -Xjit:'{scala/tools/asm/tree/analysis/Analyzer.analyze(Ljava/lang/String*}(traceFull,optLevel=warm,log=trace.log)'
I am going through the method log now, so will have an other update for you soon.
VermaSh
commented
1 year ago I was able to narrow it down further to class hierarchy table. Running with disableCHOpts fixes the failures. Next step here is to figure out what exactly about ch opts causes the failure.
jonathan-albrecht-ibm
commented
1 year ago Hi @VermaSh, just wanted to check in and see if you had any new info on this issue.
VermaSh
commented
1 year ago Hi @jonathan-albrecht-ibm, unfortunately haven't had a chance to investigate further into the failure. I am hoping to have some free bandwidth later this week as things are cooling down for the other project.
VermaSh
commented
1 year ago Haven't have able to make much progress here as I had to investigate a blocker on zLinux. I'll post an update as soon as I make progress for this failure.
jonathan-albrecht-ibm
commented
1 year ago Hi @VermaSh, just wanted to check in and see if you had any new info on this issue.
jonathan-albrecht-ibm
commented
7 months ago Hi @VermaSh, just wanted to check in again on this issue
VermaSh
commented
7 months ago @jonathan-albrecht-ibm sorry, haven't had the bandwidth to look into this.
r30shah
commented
7 months ago @Spencer-Comin Can you take a look at the issue given that is is seen with kafka ? For some reason, I can not assign this one to you.
Spencer-Comin
commented
7 months ago RE: https://github.com/eclipse-openj9/openj9/issues/14054#issuecomment-1170200239 I was able to reproduce this error with kafka 3.2.0 and semeru 11.0.21+9. As a side note, with the latest kafka (3.6.1) I do not see the error.
jonathan-albrecht-ibm
commented
6 months ago Hi @Spencer-Comin, just wanted to check if you are planning on working on this issue. It's currently unassigned.
Spencer-Comin
commented
6 months ago @jonathan-albrecht-ibm I’m off for the next two weeks; once I’m back I’ll continue working on this issue.
Spencer-Comin
commented
3 months ago I've poked around at this for the last few weeks. The issue disappears when I use Semeru 11.0.22+7. I've confirmed that the correct bytecode is produced.
249: astore 9
251: getstatic #238 // Field kafka/utils/CoreUtils$.MODULE$:Lkafka/utils/CoreUtils$;
254: aload 7
256: invokedynamic #643, 0 // InvokeDynamic #1:apply$mcV$sp:(Ljava/io/RandomAccessFile;)Lscala/runtime/java8/JFunction0$mcV$sp;
261: getstatic #51 // Field kafka/log/AbstractIndex$.MODULE$:Lkafka/log/AbstractIndex$;
264: getstatic #238 // Field kafka/utils/CoreUtils$.MODULE$:Lkafka/utils/CoreUtils$;
267: pop
268: getstatic #590 // Field org/slf4j/event/Level.WARN:Lorg/slf4j/event/Level;
271: invokevirtual #594 // Method kafka/utils/CoreUtils$.swallow:(Lscala/Function0;Lkafka/utils/Logging;Lorg/slf4j/event/Level;)V
274: aload 9
276: athrowFull disassembly here: AbstractIndex.11.0.22+7.disassembly.txt
jonathan-albrecht-ibm
commented
3 months ago Thanks @Spencer-Comin that looks good to me. I'm okay to close this issue now.
Java -version output
openjdk version "11.0.13" 2021-10-19 IBM Semeru Runtime Open Edition 11.0.13.0 (build 11.0.13+8) Eclipse OpenJ9 VM 11.0.13.0 (build openj9-0.29.0, JRE 11 Linux s390x-64-Bit Compressed References 20211021_227 (JIT enabled, AOT enabled) OpenJ9 - e1e72c497 OMR - 299b6a2d2 JCL - 2d83aa3b76 based on jdk-11.0.13+8)
Summary of problem
I build Apache Kafka project version 3.0.0 with Semeru JDK 11.0.13 on a s390x machine, and when I started the service I found the following Verify error:
The same problem is not observed with Temurin JDK 11.0.13 or with Semeru JDK 11.0.13 on a amd64 machine.
Diagnostic files
As the error message suggested, I examine the compiled Java bytecode on different environment. I found that the issue lies within this source file. The compiled code of this file is different among different JDKs and archs while other files are consistent. Here is part of the difference:
Semeru JDK 11.0.13 on s390x:
Attaching the full text here: semeru_disassembled.txt
Temurin JDK 11.0.13 on s390x (Semeru JDK 11.0.13 on amd64 is similar):
Attaching the full text here: temurin_disassembled.txt
From the comparison, we could tell that the local variable no. 9 on Temurin machine is missing on Semeru machine. There are two operations involving this variable
249: astore 9and274: aload 9, whereas the latter one was mistakenly compiled to273: aload_0on Semeru s390x machine, which leading to the next operation274: athrowto throw the class object itself (while it actually is supposed to throw local variable 9). This assumption matches what the error message is saying (kafka/log/AbstractIndexis not throwable as it was not supposed to be thrown).I compared the source code with the compiled java bytecode, and I believe the snippet above is compiled from the following source file block (line 109 - 138 from file):
Apparently, there are some bugs when compiling the code block above with Semeru on s390x, while the bugs are not present when compile on AMD64 or using Temurin JDK. The most obvious sign of the bug is the missing
9local variable, which unfortunately is not shown on the local variable table as well. I am guessing the9variable may relate to thetryblock as it is supposed to be thrown at a certain point, but I cannot get further information on that, and I also could not get a simpler reproduction test case as the issue seems to be pretty subtle and tricky.Another thing that might help with debugging this issue is the scala compilation options. In the environment above, I have been using Kafka's default scala compilation flags, which is:
And I actually found that if I turn off the inliner optimization of Scala compiler, it will leads to different Java machine code but the issue will not persist on s390x with Semeru JDK. Please see this attached file:semeru_no_inliner_disassembled.txt As mentioned, turning off inliner will lead to a different bytecode file but for this specific class
kafka/log/AbstractIndex, the local variable9and the two corresponding operation will be correctly compiled, thus the VerifyError will not emerge. So it seems the bug only happens on s390x and while the inliner is turned on.It will be really appreciated if someone could look into this error and find out why one local variable will be missing when compiling scala code with Semeru JDK11. Thank you.