Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

JIT crash for java/lang/StringConcatHelper.stringOf(Ljava/lang/Object;)Ljava/lang/String; #19369

Closed
beikov opened this issue Apr 23, 2024 · 28 comments · Fixed by #20232
Closed

Comments

@beikov
Copy link

beikov commented Apr 23, 2024

Java -version output

openjdk version "17.0.10" 2024-01-16
IBM Semeru Runtime Open Edition 17.0.10.0 (build 17.0.10+7)
Eclipse OpenJ9 VM 17.0.10.0 (build openj9-0.43.0, JRE 17 Linux s390x-64-Bit Compressed References 20240116_630 (JIT enabled, AOT enabled)
OpenJ9 - 2c3d78b
OMR - ea8124dbc
JCL - 2aad089841f based on jdk-17.0.10+7)

Summary of problem

Running the Hibernate ORM testsuite triggers a JVM crash. Also see https://ci.hibernate.org/job/hibernate-orm-pipeline/job/wip%2F7.0/20/execution/node/66/log/

The problem can be reproduced by running ./gradlew check -PexcludeTests=**/KotlinProjectTests* -Plog-test-progress=true --stacktrace with the wip/7.0 branch of Hibernate ORM.

Diagnostic files

javacore.20240423.090841.2949679.0002.txt
jitdump.20240423.090841.2949679.0004.dmp
Snap.20240423.090841.2949679.0003.trc.txt

Unhandled exception
Type=Segmentation error vmState=0x00000000
J9Generic_Signal_Number=00000018 Signal_Number=0000000b Error_Value=00000000 Signal_Code=00000001
Handler1=000003FFAA6C9410 Handler2=000003FFAA5B19D8 InaccessibleAddress=0000000010000000
gpr0=0000000000191C00 gpr1=0000000010000000 gpr2=0000000010000000 gpr3=000003FF89AB91FA
gpr4=000003FF883CBEF4 gpr5=00000000023A83B8 gpr6=0000000010000000 gpr7=00000000319EA0C0
gpr8=0000000010000000 gpr9=000003FF8992DE00 gpr10=000003FF8992DDF4 gpr11=0000000000318F00
gpr12=00000000EC5C95A8 gpr13=000000000006D200 gpr14=000003FF8992DE84 gpr15=000003FFAB2F1BA0
psw=000003FF89AB9226 mask=0705200180000000 fpc=00080000 bea=000003FF8992DE82
fpr0 3f40000000000000 (f: 0.000000, d: 4.882812e-04)
fpr1 000003ffaaf9f968 (f: 2868508928.000000, d: 2.172219e-311)
fpr2 00000000001d28d8 (f: 1911000.000000, d: 9.441594e-318)
fpr3 0000000000000007 (f: 7.000000, d: 3.458460e-323)
fpr4 000003ffa4000a78 (f: 2751465984.000000, d: 2.172161e-311)
fpr5 000003ffa4000f70 (f: 2751467264.000000, d: 2.172161e-311)
fpr6 0000000000000000 (f: 0.000000, d: 0.000000e+00)
fpr7 9ae13b28b86404a3 (f: 3093562624.000000, d: -3.322044e-179)
fpr8 0000000030678b80 (f: 812092288.000000, d: 4.012269e-315)
fpr9 0000000002f39458 (f: 49517656.000000, d: 2.446497e-316)
fpr10 00000000306783a8 (f: 812090304.000000, d: 4.012259e-315)
fpr11 0000000000000000 (f: 0.000000, d: 0.000000e+00)
fpr12 000616c33b5900b9 (f: 995688640.000000, d: 8.467681e-309)
fpr13 000003fecc016a08 (f: 3422644736.000000, d: 2.170371e-311)
fpr14 0000000000040000 (f: 262144.000000, d: 1.295163e-318)
fpr15 000003fecc031588 (f: 3422754304.000000, d: 2.170371e-311)

Compiled_method=java/lang/StringConcatHelper.stringOf(Ljava/lang/Object;)Ljava/lang/String;
Target=2_90_20240116_630 (Linux 4.18.0-425.3.1.el8.s390x)
CPU=s390x (8 logical CPUs) (0x3ddbc6000 RAM)
----------- Stack Backtrace -----------
 (0x000003FF89AB9226 [<unknown>+0x0])
---------------------------------------
JVMDUMP039I Processing dump event "gpf", detail "" at 2024/04/23 09:08:41 - please wait.
JVMDUMP032I JVM requested System dump using '/home/linux1/workspace/hibernate-orm-pipeline_wip_7.0/hibernate-core/target/OOM-dump/core.20240423.090841.2949679.0001.dmp' in response to an event
JVMPORT030W /proc/sys/kernel/core_pattern setting "|/usr/lib/systemd/systemd-coredump %P %u %g %s %t %c %h %e" specifies that the core dump is to be piped to an external program.  Attempting to rename either core or core.2950261.  Review the manual for the external program to find where the core dump is written and ensure the program does not truncate it.

JVMPORT049I The core file created by child process with pid = 2950261 was not found. Review the documentation for the /proc/sys/kernel/core_pattern program "|/usr/lib/systemd/systemd-coredump %P %u %g %s %t %c %h %e" to find where the core file is written and ensure that program does not truncate it.

JVMDUMP012E Error in System dump: /home/linux1/workspace/hibernate-orm-pipeline_wip_7.0/hibernate-core/target/OOM-dump/core.20240423.090841.2949679.0001.dmp
JVMDUMP032I JVM requested Java dump using '/home/linux1/workspace/hibernate-orm-pipeline_wip_7.0/hibernate-core/target/OOM-dump/javacore.20240423.090841.2949679.0002.txt' in response to an event
JVMDUMP010I Java dump written to /home/linux1/workspace/hibernate-orm-pipeline_wip_7.0/hibernate-core/target/OOM-dump/javacore.20240423.090841.2949679.0002.txt
JVMDUMP032I JVM requested Snap dump using '/home/linux1/workspace/hibernate-orm-pipeline_wip_7.0/hibernate-core/target/OOM-dump/Snap.20240423.090841.2949679.0003.trc' in response to an event
JVMDUMP010I Snap dump written to /home/linux1/workspace/hibernate-orm-pipeline_wip_7.0/hibernate-core/target/OOM-dump/Snap.20240423.090841.2949679.0003.trc
JVMDUMP032I JVM requested JIT dump using '/home/linux1/workspace/hibernate-orm-pipeline_wip_7.0/hibernate-core/target/OOM-dump/jitdump.20240423.090841.2949679.0004.dmp' in response to an event
JVMDUMP051I JIT dump occurred in 'Test worker' thread 0x000000000006D200
JVMDUMP053I JIT dump is recompiling java/lang/StringConcatHelper.stringOf(Ljava/lang/Object;)Ljava/lang/String;
JVMDUMP013I Processed dump event "gpf", detail "".
@babsingh
Copy link
Contributor

fyi @r30shah

@r30shah
Copy link
Contributor

r30shah commented Apr 23, 2024

@beikov Looking at the segmentation fault, I see that the failure is happening while executing a JIT compiled method. From the output, it seems like it has generated diagnostic files (core dump, javacore, jitdump, etc). If the test has archived core dump or it is still available, would it be possible for us to checkout that ? It would help us with diagnosing problem. NVM, saw that it failed with producing core-dump

@pshipton
Copy link
Member

Pls give the 17.0.10 Milestone 2 build a try to see if the problem still occurs.

https://github.com/ibmruntimes/semeru17-binaries/releases/tag/jdk-17.0.11%2B7_openj9-0.44.0-m2

@beikov
Copy link
Author

beikov commented Apr 23, 2024

No more JIT error with that milestone, but now we have a stackoverflow that makes no sense. The JIT seems to produce wrong code: https://ci.hibernate.org/job/hibernate-orm-pipeline/job/wip%2F7.0/21/testReport/junit/org.hibernate.orm.test.bootstrap.jpa/PersistenceUnitOverridesTests/Build___s390x_h2___Test___testCfgXmlBaseline/

It reports this SO which makes no sense:

	at java.base/java.lang.StringConcatHelper.stringOf(StringConcatHelper.java:453)
	at org.hibernate.boot.model.naming.Identifier.render(Identifier.java:222)
	at org.hibernate.boot.model.naming.Identifier.toString(Identifier.java:232)
	at java.base/java.lang.StringConcatHelper.stringOf(StringConcatHelper.java:453)
	at org.hibernate.boot.model.naming.Identifier.render(Identifier.java:222)
	at org.hibernate.boot.model.naming.Identifier.toString(Identifier.java:232)
	at java.base/java.lang.String.valueOf(String.java:4988)
	at java.base/java.lang.StringBuilder.append(StringBuilder.java:173)
	at org.hibernate.boot.model.relational.QualifiedNameParser$NameParts.<init>(QualifiedNameParser.java:50)

The methods in Identifier do not call this.toString(). The same thing works fine on x86 with the Hotspot JVM.

	public String render() {
		return isQuoted
				? '`' + getText() + '`'
				: getText();
	}

	@Override
	public String toString() {
		return render();
	}

@r30shah
Copy link
Contributor

r30shah commented Apr 23, 2024

It may be the same issue so upgrading the build did not work. Looking at the method StringConcatHelper.toString, I see that it will call Object.toString() method, that is what Identifier.toString() call is.
Given that you have a fair success in getting this to fail, I will try to reproduce this and see if I can get the core-dump.

@r30shah
Copy link
Contributor

r30shah commented Apr 23, 2024

I can reproduce this on my personal VM and now I do have a core-dump to analyze.

Following is the failing stack,

{java/lang/StringConcatHelper.stringOf} JIT
{java/lang/invoke/LambdaForm$DMH/0x00000000841cc320.invokeStatic} JIT 
{java/lang/invoke/LambdaForm$MH/0x00000000c00b4410.invoke} JIT
{java/lang/invoke/LambdaForm$MH/0x000000008479d7e0.linkToTargetMethod} JIT 
{org/hibernate/persister/entity/AbstractEntityPersister.internalInitSubclassPropertyAliasesMap} INT
{org/hibernate/persister/entity/AbstractEntityPersister.internalInitSubclassPropertyAliasesMap} JIT

Looking at the disassembly of StringConcatHelper.stringOf, we end up in this method with corrupted object (Instead of the Object, it points to an address of another JIT compiled method. Chasing down the parameter, something messed up in the last / second last method as core-dump complained about corrupt stack and I can not get proper object values to check. Looking at the code for internalInitSubclassPropertyAliasesMap , it seems to be failing while calling a code for String concatenation at [1]. I will see if this only appears to be seen on Z or I can reproduce it on X as well. Will post update on this issue.

[1]. https://github.com/hibernate/hibernate-orm/blob/2dddf6c3e24c1c9d480fadf8e055f4cac5f26766/hibernate-core/src/main/java/org/hibernate/persister/entity/AbstractEntityPersister.java#L6796C1-L6796C2

@beikov
Copy link
Author

beikov commented May 27, 2024

Any updates on this? I see you released a new version recently, but since you didn't respond here, I wanted to know if that version is supposed to fix this problem.

@r30shah
Copy link
Contributor

r30shah commented May 28, 2024

@beikov This is still under investigation, will post more detailed analysis on the investigation soon and will share which release would contain the fix, but to answer your question, the new version (0.44) that was released does not contain the fix - That would be more or less same driver that you tried in #19369 (comment).

@vij-singh
Copy link

@r30shah Any new news on this one?

@r30shah
Copy link
Contributor

r30shah commented Jun 21, 2024

@vij-singh I have been trying to reproduce this on latest nightly build - but seems like lot of changes went in https://github.com/hibernate/hibernate-orm/tree/wip/7.0 and seems like the build is failing with error in compiling java code hence it does not even reach to the point where it executes the test. I will try to rollback the repo to older commits to see if I can get the tests to execute.

@beikov
Copy link
Author

beikov commented Aug 14, 2024

I don't understand why nobody cares about this issue. This makes OpenJ9 totally unusable on s390x, maybe also on other architectures.

We are going to stop testing with s390x in Hibernate ORM 7.0 and discourage people from using OpenJ9 JDK17+ with Hibernate ORM altogether.

@r30shah
Copy link
Contributor

r30shah commented Aug 14, 2024

@beikov I am working on the issue on background and as issue is tagged fro 0.48 release, aiming to fix it by then. I do apologize it took bit long for me, but as I mentioned in #19369 (comment), with recent changes that went in hibernate I could not reproduce the failure as I started hitting following error

* Exception is:
org.gradle.api.tasks.TaskExecutionException: Execution failed for task ':hibernate-jfr:compileJava'.
	at org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter.lambda$executeIfValid$1(ExecuteActionsTaskExecuter.java:130)
	at org.gradle.internal.Try$Failure.ifSuccessfulOrElse(Try.java:282)
	at org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter.executeIfValid(ExecuteActionsTaskExecuter.java:128)
	at org.gradle.api.internal.tasks.execution.ExecuteActionsTaskExecuter.execute(ExecuteActionsTaskExecuter.java:116)
...
Caused by: org.gradle.api.internal.tasks.compile.CompilationFailedException: Compilation failed; see the compiler error output for details.
	at org.gradle.api.internal.tasks.compile.JdkJavaCompiler.execute(JdkJavaCompiler.java:61)
	at org.gradle.api.internal.tasks.compile.JdkJavaCompiler.execute(JdkJavaCompiler.java:41)

Which I saw on x86 linux as well. I had to find the commit to roll back reproduce this and continue investigation.

@beikov
Copy link
Author

beikov commented Aug 15, 2024

Our CI builds the wip/7.0 branch just fine for months already. hibernate-jfr is a module that is only included when you run with OpenJDK since that includes JFR, but OpenJ9 is not OpenJDK, so I guess something is messed up with the JDK build that you are creating.

@SanyogDeshmukh
Copy link

@beikov @r30shah I tried building hibernate with IBM Semeru java version jdk-17.0.12+7_openj9-0.46.0 and the build was successful. I didn't observe any failures.
Possible to upgrade java to jdk-17.0.12+7_openj9-0.46.0 (https://github.com/ibmruntimes/semeru17-binaries/releases/tag/jdk-17.0.12%2B7_openj9-0.46.0)?

@mbladel
Copy link

mbladel commented Sep 4, 2024

We tried upgrading Hibernate's s390x CI runner to jdk 17.0.12 (openj9-0.46.0), but the errors still persist, see for example this build scan.

@r30shah
Copy link
Contributor

r30shah commented Sep 17, 2024

I am able to reproduce this with latest nightly build. I needed to comment this part to be able to run the test with latest OpenJ9 nightly build.

Posting my analysis from one of the core-dump here. This is the stderr when it fails.

Unhandled exception
Type=Segmentation error vmState=0x00000000
J9Generic_Signal_Number=00000018 Signal_Number=0000000b Error_Value=00000000 Signal_Code=00000001
Handler1=000003FFB08CB138 Handler2=000003FFB07B1A60 InaccessibleAddress=000000001862B000
gpr0=00000000011F8B00 gpr1=000003FF8FE19D3E gpr2=000003FF8FE19D3E gpr3=000000001862C000
gpr4=000003FF8F1928EE gpr5=0000000003F09428 gpr6=000003FF8FE19D3E gpr7=0000000041590E30
gpr8=000003FF8FE19D3E gpr9=000000004158A6B0 gpr10=0000000040030538 gpr11=000003FF8E6A6100
gpr12=000003FF8E6A60F4 gpr13=00000000036FC400 gpr14=000003FF8E6A617E gpr15=000003FF8D27C3B0
psw=000003FF8E7743FC mask=0705200180000000 fpc=00080000 bea=000003FF8E774372
...
Compiled_method=java/lang/StringConcatHelper.stringOf(Ljava/lang/Object;)Ljava/lang/String;
Target=2_90_20240913_830 (Linux 5.15.0-119-generic)
CPU=s390x (16 logical CPUs) (0xfb8674000 RAM)
----------- Stack Backtrace -----------
 (0x000003FF8E7743FC [<unknown>+0x0])
---------------------------------------
JVMDUMP039I Processing dump event "gpf", detail "" at 2024/09/17 15:01:36 - please wait.
JVMDUMP032I JVM requested System dump using '/root/19369/hibernate-orm-copy/hibernate-core/target/OOM-dump/core.20240917.150136.3155167.0001.dmp' in response to an event

Looking at the disassembly of java/lang/StringConcatHelper.stringOf(Ljava/lang/Object;)Ljava/lang/String;,

(0x000003ff8e7743fc-258)/259bi
0x3ff8e7742fa {java/lang/StringConcatHelper.stringOf} +0                        e31050000004 lg        %r1, 0(%r5)
0x3ff8e774300 {java/lang/StringConcatHelper.stringOf} +6                        e3e05ff8ff24 stg       %r14, -8(%r5)
0x3ff8e774306 {java/lang/StringConcatHelper.stringOf} +12                       e3505fc0ff71 lay       %r5, -0x40(%r5)
0x3ff8e77430c {java/lang/StringConcatHelper.stringOf} +18                       e350d0500021 clg       %r5, 0x50(%r13)  J9VMThread.stackOverflowMark
0x3ff8e774312 {java/lang/StringConcatHelper.stringOf} +24                       a744009c     jl        0x3ff8e77444a C>> +336
0x3ff8e774316 {java/lang/StringConcatHelper.stringOf} +28                       e36050180024 stg       %r6, 0x18(%r5)  <<< ^+354
0x3ff8e77431c {java/lang/StringConcatHelper.stringOf} +34                       b9040061     lgr       %r6, %r1
0x3ff8e774320 {java/lang/StringConcatHelper.stringOf} +38                       c0100ecdbd44 larl      %r1, 0x3ffac12bda8 MemBlk - /home/jenkins/workspace/Build_JDK17_s390x_linux_Nightly/openj9/runtime/compiler/env/RawAllocator.hpp:71 +208
0x3ff8e774326 {java/lang/StringConcatHelper.stringOf} +44                       e55d10000000 clfhsi    0(%r1), 0
0x3ff8e77432c {java/lang/StringConcatHelper.stringOf} +50                  *    a7640049     jlh       0x3ff8e7743be C>> +196
0x3ff8e774330 {java/lang/StringConcatHelper.stringOf} +54                  |>>  b9020066     ltgr      %r6, %r6 <<< ^+214 ^+254
0x3ff8e774334 {java/lang/StringConcatHelper.stringOf} +58                  |||* a784002c     je        0x3ff8e77438c C>> +146  // >>> -1:13 ldc 5 (java.lang.String) "null" <<< +1
0x3ff8e774338 {java/lang/StringConcatHelper.stringOf} +62                  |||| e3006000003a llzrgf    %r0, 0(%r6)
0x3ff8e77433e {java/lang/StringConcatHelper.stringOf} +68                  |||| c20e011f8b00 clgfi     %r0, 0x11f8b00 J9Class - {java/lang/String}
0x3ff8e774344 {java/lang/StringConcatHelper.stringOf} +74                  |||| a764000d     jlh       0x3ff8e77435e C>> +100
0x3ff8e774348 {java/lang/StringConcatHelper.stringOf} +78                  |||| b9040026     lgr       %r2, %r6 <<< ^+142
0x3ff8e77434c {java/lang/StringConcatHelper.stringOf} +82                  |||| e3e050380004 lg        %r14, 0x38(%r5)
0x3ff8e774352 {java/lang/StringConcatHelper.stringOf} +88                  |||| e36050180004 lg        %r6, 0x18(%r5)
0x3ff8e774358 {java/lang/StringConcatHelper.stringOf} +94                  |||| 41505040     la        %r5, 0x40(%r5)
0x3ff8e77435c {java/lang/StringConcatHelper.stringOf} +98                  |||| 07fe         br        %r14
                                                                           ||||
0x3ff8e77435e {java/lang/StringConcatHelper.stringOf} +100                 |||| b9040016     lgr       %r1, %r6 <<< +74
0x3ff8e774362 {java/lang/StringConcatHelper.stringOf} +104                 |||| e3306000003a llzrgf    %r3, 0(%r6)
0x3ff8e774368 {java/lang/StringConcatHelper.stringOf} +110                 |||| c001011f8b00 lgfi      %r0, 0x11f8b00 J9Class - {java/lang/String}
0x3ff8e77436e {java/lang/StringConcatHelper.stringOf} +116                 |||| b9210030     clgr      %r3, %r0
0x3ff8e774372 {java/lang/StringConcatHelper.stringOf} +120                 |||| a7640045     jlh       0x3ff8e7743fc C>> +258
...
0x3ff8e7743fc {java/lang/StringConcatHelper.stringOf} +258                      e3e03fc8ff04 lg        %r14, -0x38(%r3) <<< +120

Seems like it fails trying to load from the function table from what it thinks is J9Class pointer. Looking at the value of R3, it does not look like a valid J9Class pointer which is loaded from GPR1 which does not contain valid object.

The call stack looks like following,

where
0x000003ff8e7743fc {java/lang/StringConcatHelper.stringOf} JIT [0000000003f09428]
0x000003ff8e6a617e {java/lang/invoke/LambdaForm$DMH/0x00000000ac1c1890.invokeStatic} JIT [0000000003f09468]
0x000003ff8f1929b0 {java/lang/invoke/LambdaForm$MH/0x00000000aeee4fc0.invoke} JIT [0000000003f094b8]
0x000003ff8e896a9a {java/lang/invoke/LambdaForm$MH/0x00000000acaad650.linkToTargetMethod} JIT [0000000003f09540]
0x000003ffafb4c45d {org/hibernate/persister/entity/AbstractEntityPersister.internalInitSubclassPropertyAliasesMap} INT [0x3f095a0-0x3f096a0]
0x000003ff8f82cd44 {org/hibernate/persister/entity/AbstractEntityPersister.internalInitSubclassPropertyAliasesMap} JIT [0000000003f09690]
0x000003ff8f652a64 {org/hibernate/persister/entity/AbstractEntityPersister.initSubclassPropertyAliasesMap} JIT [0000000003f097c0]
0x000003ff8fe70e18 {org/hibernate/persister/entity/SingleTableEntityPersister.<init>} JIT [0000000003f098d8]
0x000003feec50f9a4 {jdk/internal/reflect/GeneratedConstructorAccessor88.newInstance} INT [0x3f09a50-0x3f09ae0]
0x000003ff8e84bff2 {java/lang/reflect/Constructor.newInstanceWithCaller} JIT [0000000003f09ad8]
0x000003ff8e84c670 {java/lang/reflect/Constructor.newInstance} JIT [0000000003f09b78]
0x000003ffafaaacd8 {org/hibernate/persister/internal/PersisterFactoryImpl.createEntityPersister} INT [0x3f09c10-0x3f09ce0]
0x000003ff900cd25c {org/hibernate/metamodel/model/domain/internal/MappingMetamodelImpl.processBootEntities} JIT [0000000003f09cc0]
0x000003ff8fe81274 {org/hibernate/metamodel/model/domain/internal/MappingMetamodelImpl.finishInitialization} JIT [0000000003f09d98]
0x000003ffaf854026 {org/hibernate/internal/SessionFactoryImpl.initializeMappingModel} INT [0x3f09ed8-0x3f09f88]
0x000003ff8fc9f428 {org/hibernate/internal/SessionFactoryImpl.<init>} JIT [0000000003f09f68]
0x000003ffaf4e378b {org/hibernate/boot/internal/SessionFactoryBuilderImpl.build} INT [0x3f0a090-0x3f0a0c0]
0x000003fee002a603 {org/hibernate/jpa/boot/internal/EntityManagerFactoryBuilderImpl.build} INT [0x3f0a0c8-0x3f0a118]
0x000003ffad4bd8cc {org/hibernate/orm/test/jpa/BaseEntityManagerFunctionalTestCase.buildEntityManagerFactory} INT [0x3f0a120-0x3f0a158]
0x000003febc003acc {jdk/internal/reflect/GeneratedMethodAccessor126.invoke} INT [0x3f0a160-0x3f0a1f0]
0x000003ff909eb5ac {java/lang/reflect/Method.invoke} JIT [0000000003f0a1e0]
0x000003ffaef5537b {org/junit/runners/model/FrameworkMethod$1.runReflectiveCall} INT [0x3f0a298-0x3f0a2c0]
0x000003ffaef55801 {org/junit/internal/runners/model/ReflectiveCallable.run} INT [0x3f0a2c8-0x3f0a2f8]
0x000003ffaee8737f {org/junit/runners/model/FrameworkMethod.invokeExplosively} INT [0x3f0a300-0x3f0a338]
0x000003ffaee73ced {org/junit/internal/runners/statements/RunBefores.invokeMethod} INT [0x3f0a340-0x3f0a370]
0x000003ffaee73c75 {org/junit/internal/runners/statements/RunBefores.evaluate} INT [0x3f0a378-0x3f0a418]
0x000003ff903f3cb6 {org/junit/internal/runners/statements/RunAfters.evaluate} JIT [0000000003f0a418]
0x000003ff8fbcb232 {java/util/concurrent/FutureTask.run} JIT [0000000003f0a4c0]
0x000003ffac2247bd {java/lang/Thread.run} INT [0x3f0a5b0-0x3f0a5c8]
0x000003ffabc30140 {libj9jit29.so}{returnFromJIT0} [000003ff8d27c3b0]

I have looked at the other frames after the Interpreter frame (0x000003ffafb4c45d {org/hibernate/persister/entity/AbstractEntityPersister.internalInitSubclassPropertyAliasesMap} INT [0x3f095a0-0x3f096a0]) to chase from where the corrupt object is coming from. First JIT method after that interpreter frame looks like following,

(kca) (0x000003ff8e896a9a-172)/173bi
0x3ff8e8969ee {java/.../0x00000000acaad650.linkToTargetMethod} +0                        e31050100004 lg        %r1, 0x10(%r5)
0x3ff8e8969f4 {java/.../0x00000000acaad650.linkToTargetMethod} +6                        e32050080004 lg        %r2, 8(%r5)
0x3ff8e8969fa {java/.../0x00000000acaad650.linkToTargetMethod} +12                       e33050000004 lg        %r3, 0(%r5)
0x3ff8e896a00 {java/.../0x00000000acaad650.linkToTargetMethod} +18                       e3e05ff8ff24 stg       %r14, -8(%r5)
0x3ff8e896a06 {java/.../0x00000000acaad650.linkToTargetMethod} +24                       e3505fa0ff71 lay       %r5, -0x60(%r5)
0x3ff8e896a0c {java/.../0x00000000acaad650.linkToTargetMethod} +30                       e350d0500021 clg       %r5, 0x50(%r13)  J9VMThread.stackOverflowMark
...

Looking at the values on the Java Stack when we enter this method,

(kca) what (0x0000000003f095a0-8)/4
0x3f09598: 0x000003ffabc306d0 {libj9jit29.so}{returnFromJITL} +0 // Return Address
0x3f095a0: 0x0000000042d6f718 Obj - {java/lang/invoke/BoundMethodHandle$Species_LLLLLLL}T // Third Arg
0x3f095a8: 0x0000000040030538 Obj - {java/lang/String}T "ae" // Second Arg
0x3f095b0: 0x000003ff8fe19d3e {java/util/stream/StreamSpliterators$WrappingSpliterator.tryAdvance} +1354 // First  Arg

Seems like we are calling this JIT compiled method from interpreter, where the first argument does not point to valid object.
Need to chase further from where that object is coming from. Looking at the stackslots, I can confirm that the last method before we execute interpreted method sets out argument correctly (0x000003ff8f82cd44 {org/hibernate/persister/entity/AbstractEntityPersister.internalInitSubclassPropertyAliasesMap} JIT [0000000003f09690]).

I have uploaded the result files on Linux on Z system in internal farm in /team/rahil/19369.

@r30shah
Copy link
Contributor

r30shah commented Sep 17, 2024

@TobiAjila Can I get some help in nailing this one down? I am trying to find out from where the corrupt object is coming from and can not see the point where it gets corrupted.

@tajila
Copy link
Contributor

tajila commented Sep 17, 2024

Looking at the last interpreter frame

<1dac700> *** BEGIN STACK WALK, flags = 00400001 walkThread = 31,115,008 ***
<1dac700> 	ITERATE_O_SLOTS
<1dac700> 	RECORD_BYTECODE_PC_OFFSET
<1dac700> Initial values: walkSP = 0x0000000003804690, PC = 0x000003FFAFC5681D, literals = 0x0000000003A4CD58, A0 = 0x0000000003804790, j2iFrame = 0x0000000003804728, decomp = 0x0000000000000000
<1dac700> J2I frame: bp = 0x0000000003804728, sp = 0x0000000003804690, pc = 0x000003FFAFC5681D, cp = 0x0000000003A430A0, arg0EA = 0x0000000003804790, flags = 0x0000000010000000
<1dac700> 	Method: org/hibernate/persister/entity/AbstractEntityPersister.internalInitSubclassPropertyAliasesMap(Ljava/lang/String;Ljava/util/List;)V !j9method 0x0000000003A4CD58
<1dac700> 	Bytecode index = 77
<1dac700> 	Using local mapper
<1dac700> 	Locals starting at 0x0000000003804790 for 0x000000000000000D slots
<1dac700> 		O-Slot: a0[0x0000000003804790] = 0x00000000FF3CE520
<1dac700> 		O-Slot: a1[0x0000000003804788] = 0x0000000042EB0CF8
<1dac700> 		I-Slot: a2[0x0000000003804780] = 0x00000000FF078BB8
<1dac700> 		I-Slot: t3[0x0000000003804778] = 0x0000000000000000
<1dac700> 		O-Slot: t4[0x0000000003804770] = 0x0000000042317ED0
<1dac700> 		O-Slot: t5[0x0000000003804768] = 0x00000000FF4A6538
<1dac700> 		O-Slot: t6[0x0000000003804760] = 0x00000000FF07C228
<1dac700> 		I-Slot: t7[0x0000000003804758] = 0x0000000000000000
<1dac700> 		I-Slot: t8[0x0000000003804750] = 0x0000000000000000
<1dac700> 		I-Slot: t9[0x0000000003804748] = 0x0000000000000000
<1dac700> 		I-Slot: t10[0x0000000003804740] = 0x0000000000000000
<1dac700> 		I-Slot: t11[0x0000000003804738] = 0x0000000000000000
<1dac700> 		I-Slot: t12[0x0000000003804730] = 0x0000000000000000

It appears that we are doing an invokedynamic at bytecode 77 77 invokedynamic 54 bsm #47:makeConcatWithConstants(Ljava/lang/String;Ljava/lang/String;)Ljava/lang/String; @r30shah can you confirm this?

If so the args should be:

!j9object 0x0000000042EB0CF8
J9VMJavaLangString at 0x0000000042EB0CF8 {
struct J9Class* clazz = !j9class 0x1DD3B00 // java/lang/String
Object flags = 0x00000000;
[B value = !fj9object 0x42eb0d10 (offset = 0) (java/lang/String)
B coder = 0x00000000 (offset = 4) (java/lang/String)
I hash = 0x003164AE (offset = 8) (java/lang/String)
Z hashIsZero = 0x00000000 (offset = 12) (java/lang/String)
"info"
}

and

> !j9object 0x00000000433A2A60
J9VMJavaLangString at 0x00000000433A2A60 {
struct J9Class* clazz = !j9class 0x1DD3B00 // java/lang/String
Object flags = 0x00000030;
[B value = !fj9object 0x433a2a78 (offset = 0) (java/lang/String)
B coder = 0x00000000 (offset = 4) (java/lang/String)
I hash = 0x7111CB48 (offset = 8) (java/lang/String)
Z hashIsZero = 0x00000000 (offset = 12) (java/lang/String)
"seflRefEntityEmbedded"
}

@r30shah
Copy link
Contributor

r30shah commented Sep 17, 2024

Looking at the failing stack @TobiAjila you pointed - It does fail in the StringConcatHelper.stringOf method, where Object argument we enter into is corrupted.
Here is the failing stack,

(kca) where
0x000003ff90be7094 {java/lang/StringConcatHelper.stringOf} JIT [0000000003804510]
0x000003ff90ff6a7e {java/lang/invoke/LambdaForm$DMH/0x00000000ac1c18f0.invokeStatic} JIT [0000000003804558]
0x000003ff913848b0 {java/lang/invoke/LambdaForm$MH/0x00000000aef0f6e0.invoke} JIT [00000000038045a8]
0x000003ff90cb1e9a {java/lang/invoke/LambdaForm$MH/0x00000000acaa9730.linkToTargetMethod} JIT [0000000003804630]
0x000003ffafc5681d {org/hibernate/persister/entity/AbstractEntityPersister.internalInitSubclassPropertyAliasesMap} INT [0x3804690-0x3804790]
0x000003ff91ba8558 {org/hibernate/persister/entity/AbstractEntityPersister.internalInitSubclassPropertyAliasesMap} JIT [0000000003804780]

Looking at the JIT compiled code starting from top method,

For StringConcatHelper.stringOf, here is the disassembly,

(0x000003ff90be7094-154)/155bi
0x3ff90be6ffa {java/lang/StringConcatHelper.stringOf} +0                        e31050000004 lg        %r1, 0(%r5)
0x3ff90be7000 {java/lang/StringConcatHelper.stringOf} +6                        e3e05ff8ff24 stg       %r14, -8(%r5)
0x3ff90be7006 {java/lang/StringConcatHelper.stringOf} +12                       e3505fb8ff71 lay       %r5, -0x48(%r5)
0x3ff90be700c {java/lang/StringConcatHelper.stringOf} +18                       e350d0500021 clg       %r5, 0x50(%r13)  J9VMThread.stackOverflowMark
0x3ff90be7012 {java/lang/StringConcatHelper.stringOf} +24                       a7440098     jl        0x3ff90be7142 C>> +328
0x3ff90be7016 {java/lang/StringConcatHelper.stringOf} +28                       d71750285028 xc        0x28(0x18, %r5), 0x28(%r5)  <<< ^+346
0x3ff90be701c {java/lang/StringConcatHelper.stringOf} +34                       e31050480024 stg       %r1, 0x48(%r5)
0x3ff90be7022 {java/lang/StringConcatHelper.stringOf} +40                       c0100daa26c3 larl      %r1, 0x3ffac12bda8 MemBlk - /home/jenkins/workspace/Build_JDK17_s390x_linux_Nightly/openj9/runtime/compiler/env/RawAllocator.hpp:71 +208
0x3ff90be7028 {java/lang/StringConcatHelper.stringOf} +46                       e55d10000000 clfhsi    0(%r1), 0
0x3ff90be702e {java/lang/StringConcatHelper.stringOf} +52                  *    a764004c     jlh       0x3ff90be70c6 C>> +204
0x3ff90be7032 {java/lang/StringConcatHelper.stringOf} +56                  |>>  e31050480004 lg        %r1, 0x48(%r5)  <<< ^+222 ^+262
0x3ff90be7038 {java/lang/StringConcatHelper.stringOf} +62                  |||  b9020011     ltgr      %r1, %r1
0x3ff90be703c {java/lang/StringConcatHelper.stringOf} +66                  |||* a7840037     je        0x3ff90be70aa C>> +176  // >>> -1:13 ldc 5 (java.lang.String) "null" <<< +1
0x3ff90be7040 {java/lang/StringConcatHelper.stringOf} +70                  |||| e3001000003a llzrgf    %r0, 0(%r1)
0x3ff90be7046 {java/lang/StringConcatHelper.stringOf} +76                  |||| c20e01dd3b00 clgfi     %r0, 0x1dd3b00 J9Class - {java/lang/String}
0x3ff90be704c {java/lang/StringConcatHelper.stringOf} +82                  |||| a764001b     jlh       0x3ff90be7082 C>> +136
...
0x3ff90be7082 {java/lang/StringConcatHelper.stringOf} +136                 |||| e31050480004 lg        %r1, 0x48(%r5)  <<< +82
0x3ff90be7088 {java/lang/StringConcatHelper.stringOf} +142         -1:5    |||| e3301000003a llzrgf    %r3, 0(%r1) // invokevirtual 48 {java/lang/Object.toString()Ljava/lang/String;}
0x3ff90be708e {java/lang/StringConcatHelper.stringOf} +148                 |||| e31050480004 lg        %r1, 0x48(%r5)
0x3ff90be7094 {java/lang/StringConcatHelper.stringOf} +154                 |||| e3e03fc8ff04 lg        %r14, -0x38(%r3)

Looking at the value in GPR1 - 0x000003ff9055b500 which matches with what we have on Java temp slot (0x48+J9SP). It should be a valid object but it seems like pointing to some some JITed Method. So we do enter StringConcatHelper.stringOf method with bad first argument.

Now checking out second method in the stack,

(0x000003ff90ff6a7e-138)/139bi
0x3ff90ff69f4 {java/.../0x00000000ac1c18f0.invokeStatic} +0                        e31050080004 lg        %r1, 8(%r5)
0x3ff90ff69fa {java/.../0x00000000ac1c18f0.invokeStatic} +6                        e32050000004 lg        %r2, 0(%r5)
0x3ff90ff6a00 {java/.../0x00000000ac1c18f0.invokeStatic} +12                       e3e05ff8ff24 stg       %r14, -8(%r5)
0x3ff90ff6a06 {java/.../0x00000000ac1c18f0.invokeStatic} +18                       e3505fb0ff71 lay       %r5, -0x50(%r5)
0x3ff90ff6a0c {java/.../0x00000000ac1c18f0.invokeStatic} +24                       e350d0500021 clg       %r5, 0x50(%r13)  J9VMThread.stackOverflowMark
0x3ff90ff6a12 {java/.../0x00000000ac1c18f0.invokeStatic} +30                       a7440083     jl        0x3ff90ff6b18 C>> +292
0x3ff90ff6a16 {java/.../0x00000000ac1c18f0.invokeStatic} +34                       eb6a50100024 stmg      %r6, %r10, 0x10(%r5)  <<< ^+310
0x3ff90ff6a1c {java/.../0x00000000ac1c18f0.invokeStatic} +40                       b9040082     lgr       %r8, %r2
0x3ff90ff6a20 {java/.../0x00000000ac1c18f0.invokeStatic} +44                       b9040061     lgr       %r6, %r1
0x3ff90ff6a24 {java/.../0x00000000ac1c18f0.invokeStatic} +48                       c00101e1b800 lgfi      %r0, 0x1e1b800 J9Class - {java/lang/invoke/DirectMethodHandle}
0x3ff90ff6a2a {java/.../0x00000000ac1c18f0.invokeStatic} +54           0:1         ec6000008070 cgite     %r6, 0 // checkcast 1 java/.../DirectMethodHandle
0x3ff90ff6a30 {java/.../0x00000000ac1c18f0.invokeStatic} +60                       e3706000003a llzrgf    %r7, 0(%r6)
0x3ff90ff6a36 {java/.../0x00000000ac1c18f0.invokeStatic} +66                  *    ec07000b8064 cgrje     %r0, %r7, 0x3ff90ff6a4c C>> +88
0x3ff90ff6a3c {java/.../0x00000000ac1c18f0.invokeStatic} +72                  |    e31070100004 lg        %r1, 0x10(%r7)
0x3ff90ff6a42 {java/.../0x00000000ac1c18f0.invokeStatic} +78                  |    e30010100020 cg        %r0, 0x10(%r1)
0x3ff90ff6a48 {java/.../0x00000000ac1c18f0.invokeStatic} +84                  |*   a764003c     jlh       0x3ff90ff6ac0 C>> +204
0x3ff90ff6a4c {java/.../0x00000000ac1c18f0.invokeStatic} +88                  >|>  e37060200016 llgf      %r7, 0x20(%r6)  <<< +66 ^+244
0x3ff90ff6a52 {java/.../0x00000000ac1c18f0.invokeStatic} +94                   ||  e36070080004 lg        %r6, 8(%r7)
0x3ff90ff6a58 {java/.../0x00000000ac1c18f0.invokeStatic} +100                  ||  e33060180004 lg        %r3, 0x18(%r6)
0x3ff90ff6a5e {java/.../0x00000000ac1c18f0.invokeStatic} +106                  ||  a7310001     tmll      %r3, 1
0x3ff90ff6a62 {java/.../0x00000000ac1c18f0.invokeStatic} +110                 *||  a774001e     jne       0x3ff90ff6a9e C>> +170
0x3ff90ff6a66 {java/.../0x00000000ac1c18f0.invokeStatic} +114                 |||  b9040018     lgr       %r1, %r8
0x3ff90ff6a6a {java/.../0x00000000ac1c18f0.invokeStatic} +118                 |||  e3603ffcff58 ly        %r6, -4(%r3)
0x3ff90ff6a70 {java/.../0x00000000ac1c18f0.invokeStatic} +124                 |||  8a600010     sra       %r6, 0x10
0x3ff90ff6a74 {java/.../0x00000000ac1c18f0.invokeStatic} +128                 |||  b9140066     lgfr      %r6, %r6
0x3ff90ff6a78 {java/.../0x00000000ac1c18f0.invokeStatic} +132                 |||  b9080063     agr       %r6, %r3
0x3ff90ff6a7c {java/.../0x00000000ac1c18f0.invokeStatic} +136         -1:10   |||  0de6         basr      %r14, %r6 Call>>  // invokestatic 9 {java/.../MethodHandle.linkToStatic(Ljava/lang/Object;Ljava/.../MemberName;)Ljava/lang/Object;}
0x3ff90ff6a7e {java/.../0x00000000ac1c18f0.invokeStatic} +138                 |||  b9040062     lgr       %r6, %r2

In above frame object was loaded from GPR8 (which was unchanged in top method and I can confirm the bad value in GPR8. In the beginning of this invokeStatic method, I so see that GPR8 was loaded with the value in GPR2 which is second argument to the invokeStatic method.

Looking into the next method which is java/lang/invoke/LambdaForm$MH/0x00000000aef0f6e0.invoke - I see that GPR2 is loaded with GPR6 before calling and I can confirm value of GPR6 on the Java Stack which was stored in above invokeStatic method.

0x3ff913847ee {java/.../0x00000000aef0f6e0.invoke} +0                        e31050100004 lg        %r1, 0x10(%r5)
0x3ff913847f4 {java/.../0x00000000aef0f6e0.invoke} +6                        e32050080004 lg        %r2, 8(%r5)
0x3ff913847fa {java/.../0x00000000aef0f6e0.invoke} +12                       e33050000004 lg        %r3, 0(%r5)
0x3ff91384800 {java/.../0x00000000aef0f6e0.invoke} +18                       e3e05ff8ff24 stg       %r14, -8(%r5)
0x3ff91384806 {java/.../0x00000000aef0f6e0.invoke} +24                       e3505f78ff71 lay       %r5, -0x88(%r5)
0x3ff9138480c {java/.../0x00000000aef0f6e0.invoke} +30                       e350d0500021 clg       %r5, 0x50(%r13)  J9VMThread.stackOverflowMark
0x3ff91384812 {java/.../0x00000000aef0f6e0.invoke} +36                       a7440467     jl        0x3ff913850e0 C>> +2290
0x3ff91384816 {java/.../0x00000000aef0f6e0.invoke} +40                       eb6c50280024 stmg      %r6, %r12, 0x28(%r5)  <<< ^+2308
0x3ff9138481c {java/.../0x00000000aef0f6e0.invoke} +46                       b9040062     lgr       %r6, %r2
...
0x3ff9138488c {java/.../0x00000000aef0f6e0.invoke} +158                      b9040026     lgr       %r2, %r6
0x3ff91384890 {java/.../0x00000000aef0f6e0.invoke} +162                      b9040071     lgr       %r7, %r1
0x3ff91384894 {java/.../0x00000000aef0f6e0.invoke} +166                      b90400a3     lgr       %r10, %r3
0x3ff91384898 {java/.../0x00000000aef0f6e0.invoke} +170                      e3b0cffcff58 ly        %r11, -4(%r12)
0x3ff9138489e {java/.../0x00000000aef0f6e0.invoke} +176                      8ab00010     sra       %r11, 0x10
0x3ff913848a2 {java/.../0x00000000aef0f6e0.invoke} +180                      b91400bb     lgfr      %r11, %r11
0x3ff913848a6 {java/.../0x00000000aef0f6e0.invoke} +184                      b90800bc     agr       %r11, %r12
0x3ff913848aa {java/.../0x00000000aef0f6e0.invoke} +188                      b9040019     lgr       %r1, %r9
0x3ff913848ae {java/.../0x00000000aef0f6e0.invoke} +192         -1:17        0deb         basr      %r14, %r11 Call>>  // invokevirtual 8 {java/.../MethodHandle.invokeBasic(Ljava/lang/Object;)Ljava/lang/Object;}
0x3ff913848b0 {java/.../0x00000000aef0f6e0.invoke} +194                      b904003a     lgr       %r3, %r10

Now checking the next method (0x00000000acaa9730.linkToTargetMethod ) that is the first JIT compiled method called from interpreted internalInitSubclassPropertyAliasesMap,

0x3ff90cb1dee {java/.../0x00000000acaa9730.linkToTargetMethod} +0                        e31050100004 lg        %r1, 0x10(%r5)
0x3ff90cb1df4 {java/.../0x00000000acaa9730.linkToTargetMethod} +6                        e32050080004 lg        %r2, 8(%r5)
0x3ff90cb1dfa {java/.../0x00000000acaa9730.linkToTargetMethod} +12                       e33050000004 lg        %r3, 0(%r5)
0x3ff90cb1e00 {java/.../0x00000000acaa9730.linkToTargetMethod} +18                       e3e05ff8ff24 stg       %r14, -8(%r5)
0x3ff90cb1e06 {java/.../0x00000000acaa9730.linkToTargetMethod} +24                       e3505fa0ff71 lay       %r5, -0x60(%r5)
0x3ff90cb1e0c {java/.../0x00000000acaa9730.linkToTargetMethod} +30                       e350d0500021 clg       %r5, 0x50(%r13)  J9VMThread.stackOverflowMark
0x3ff90cb1e12 {java/.../0x00000000acaa9730.linkToTargetMethod} +36                       a74400af     jl        0x3ff90cb1f70 C>> +386
0x3ff90cb1e16 {java/.../0x00000000acaa9730.linkToTargetMethod} +40                       eb6b50180024 stmg      %r6, %r11, 0x18(%r5)  <<< ^+404
0x3ff90cb1e1c {java/.../0x00000000acaa9730.linkToTargetMethod} +46                       b9040081     lgr       %r8, %r1
0x3ff90cb1e20 {java/.../0x00000000acaa9730.linkToTargetMethod} +50                       b9040072     lgr       %r7, %r2
0x3ff90cb1e24 {java/.../0x00000000acaa9730.linkToTargetMethod} +54                       b9040093     lgr       %r9, %r3
...
0x3ff90cb1e7a {java/.../0x00000000acaa9730.linkToTargetMethod} +140                 |||| b9040019     lgr       %r1, %r9
0x3ff90cb1e7e {java/.../0x00000000acaa9730.linkToTargetMethod} +144                 |||| b9040028     lgr       %r2, %r8
0x3ff90cb1e82 {java/.../0x00000000acaa9730.linkToTargetMethod} +148                 |||| b9040037     lgr       %r3, %r7
0x3ff90cb1e86 {java/.../0x00000000acaa9730.linkToTargetMethod} +152                 |||| e3604ffcff58 ly        %r6, -4(%r4)
0x3ff90cb1e8c {java/.../0x00000000acaa9730.linkToTargetMethod} +158                 |||| 8a600010     sra       %r6, 0x10
0x3ff90cb1e90 {java/.../0x00000000acaa9730.linkToTargetMethod} +162                 |||| b9140066     lgfr      %r6, %r6
0x3ff90cb1e94 {java/.../0x00000000acaa9730.linkToTargetMethod} +166                 |||| b9080064     agr       %r6, %r4
0x3ff90cb1e98 {java/.../0x00000000acaa9730.linkToTargetMethod} +170         -1:6    |||| 0de6         basr      %r14, %r6 Call>>  // invokevirtual 6 {java/.../MethodHandle.invokeBasic(Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object;}
0x3ff90cb1e9a {java/.../0x00000000acaa9730.linkToTargetMethod} +172                 |||| b9040062     lgr       %r6, %r2

I do see that GPR2 is loaded from GPR8 which contains the first argument with which this method was called. Now looking at the values on the Java stack in this method's frame,

 what ($r5+0x48+0x50+0x88+0x60-8)/4
0x3804688: 0x000003ffb2a306d0 {libj9jit29.so}{returnFromJITL} +0 // Return Address 
0x3804690: 0x00000000420ef788 Obj - {java/lang/invoke/BoundMethodHandle$Species_LLLLLLL}T // Third Argument
0x3804698: 0x0000000042eb0cf8 Obj - {java/lang/String}T "no" // Second Argument
0x38046a0: 0x000003ff9055b500 {java/util/Spliterators$1Adapter.hasNext} +6 // First Argument

The frame below this is the interpreted AbstractEntityPersister.internalInitSubclassPropertyAliasesMap which is called from JIT compiled AbstractEntityPersister.internalInitSubclassPropertyAliasesMap. I am trying to understand what could have gone wrong here. I do see in the stack slots before we corrupt message the correct J9Object, but not sure how we ended with corrupted value.

I am going to take a look at the JIT compiled code for internalInitSubclassPropertyAliasesMap and see how recursive call pans out.

@JamesKingdon
Copy link
Contributor

Hi, I'm working on what looks like a similar case on x86. In the example I've been looking at it looks like OSR is involved - any sign of OSR in your cases?

0x0000755f5499a0dc {java/lang/StringConcatHelper.stringOf} JIT [0x111e450]								// bad rax
0x0000755f54e09161 {java/lang/invoke/LambdaForm$DMH/0x00000000d03bd9b0.invokeStatic} JIT [0x111e460]	// bad rsi
0x0000755f54e0a0d0 {java/lang/invoke/LambdaForm$MH/0x00000000f4039a90.invoke} JIT [0x111e480]			// rsi passed unchanged
0x0000755f54e0938d {java/lang/invoke/LambdaForm$MH/0x00000000d056dab0.linkToTargetMethod} JIT [0x111e4e0] // bad p1 on stack
0x0000755e5806811e {org/jboss/weld/bean/proxy/ProxyFactory.getEnclosingPrefix} INT [0x111e530-0x111e5c0] [ELS: 0x755fd4ef6a20] // in interpreter after osr
0x0000755f5428492d {org/jboss/weld/bean/proxy/ProxyFactory.getProxyName} JIT [0x111e5c0]		// passed a reasonable param, but called jit'd body

Quoting from my last update:

getProxyName passed a reasonable param to getEnclosingPrefix, but called the jit compiled version of that method. The compiled version had been patched after some of the methods inlined into it had been unloaded, with the purpose of the patch being to leave the compiled body and continue execution in the interpreter.

@r30shah
Copy link
Contributor

r30shah commented Sep 18, 2024

Hi @JamesKingdon I do think that some sort of redefinition / class unloading is causing the call to interpreted call, but can not say for sure, but can checkout to see if I am seeing similar behavior.

@r30shah
Copy link
Contributor

r30shah commented Sep 18, 2024

I reproduced the failure again, this time with verbose option to dump OSR details. In this iteration of the failure, I am seeing the test to fail with following stack trace

(kca) where
0x000003ff69fcd90c {java/lang/StringConcatHelper.stringOf} JIT [000000000395b020]
0x000003ff6a89238e {java/lang/invoke/LambdaForm$DMH/0x0000000088344da0.invokeStatic} JIT [000000000395b068]
0x000003ff6a5a03b4 {java/lang/invoke/LambdaForm$MH/0x000000008ac96fb0.invoke} JIT [000000000395b0c0]
0x000003ff6a93cd82 {java/lang/invoke/LambdaForm$MH/0x0000000088559560.linkToTargetMethod} JIT [000000000395b140]
0x000003ff8a1a4506 {org/hibernate/boot/model/naming/Identifier.render} INT [0x395b190-0x395b1c8]

Same issue where object we should be coming into StringConcatHelper is corrupted. In the JIT verbose log, I can see the OSR details matching the bytecode (That in Identifier.render(), calls String concatenation helper),

#OSRd: 1F36500   Jitted body:    org/hibernate/boot/model/naming/Identifier.render()Ljava/lang/String;
#OSRd: 1F36500   osrBuffer=000003FEB400FE78 osrFrame=000003FEB400FE88, osrReturnAddress=000003FF878B0650 osrScratchBuffer=000003FEB400FEF8 osrJittedFrameCopy=000003FEB400FF38
#OSRd: 1F36500     OSRBuffer: numberOfFrames=1 jitPC=000003FF6AC3CF78
#OSRd: 1F36500     OSRFrame: j9method=0000000001B74500 bytecodePC=8a1a4506 numberOfLocals=3 maxStack=4 pendingStackHeight=0 monitorEnterRecords=0000000000000000
#OSRd: 1F36500       local  2: 00000000420D3BA0
#OSRd: 1F36500       local  1: 0000000000000000
#bj
#OSRd: 1F36500       local  0: 00000000FDB28418
#OSRd: 1F36500   1 mappings
#OSRd: 1F36500     Skip mapping @1068 <= 1662 with 0 symbols

This suggests that at some point, we invalidated the compiled code Identifier.render() and executed interpreted version and messed up with the preparing the frame. As I am seeing consistently this happening around String Concatenation, going to attempt and create a unit test to make it easier to work with.

@JamesKingdon Thanks for pointing out, I do now think this is same issue.

@jdmpapin
Copy link
Contributor

I've opened #20232 to fix this

@jdmpapin
Copy link
Contributor

Reopening since the fix still needs to go into 0.48

Copy link

Issue Number: 19369
Status: Closed
Actual Components: comp:jit, userRaised, arch:z, os:linux, triageRequired
Actual Assignees: No one :(
PR Assignees: No one :(

@beikov
Copy link
Author

beikov commented Oct 10, 2024

Is the fix part of the 0.48-m1 release?

@pshipton
Copy link
Member

Yes, the PR #20242 is included in 0.48 M1.

IBM Semeru Runtime Open Edition 17.0.13.0-m1 (build 17.0.13+10)
Eclipse OpenJ9 VM 17.0.13.0-m1 (build v0.48.0-release-8899b66789, JRE 17 Linux amd64-64-Bit Compressed References 20241015_859 (JIT enabled, AOT enabled)
OpenJ9   - 8899b66789
OMR      - f8f0d789a
JCL      - 8e2f05376ed based on jdk-17.0.13+10)

openj9-0.48m1.txt

@beikov
Copy link
Author

beikov commented Oct 10, 2024

Looks like the new version fixes the problem. Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment