JDK-8322854 : Incorrect rematerialization of scalar replaced objects in C2
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 22,23
  • Priority: P2
  • Status: Closed
  • Resolution: Fixed
  • Submitted: 2024-01-02
  • Updated: 2024-08-07
  • Resolved: 2024-02-13
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 23
23 b10Fixed
Related Reports
Relates :  
JDK-8324050 - Issue store-store barrier after re-materializing objects during deoptimization
Relates :  
JDK-8324688 - C2: Disable ReduceAllocationMerges by default
Relates :  
JDK-8287061 - Support for rematerializing scalar replaced objects participating in allocation merges
Description
The following test failed in the JDK23 CI:

java/lang/String/StringRacyConstructor.java

Here's a snippet from the log file:

#section:junit
----------messages:(7/444)----------
command: junit -XX:+CompactStrings test.java.lang.String.StringRacyConstructor
reason: User specified action: run junit/othervm -XX:+CompactStrings test.java.lang.String.StringRacyConstructor 
started: Mon Jan 01 10:17:52 UTC 2024
Mode: othervm [/othervm specified]
Additional options from @modules: --add-modules java.base --add-opens java.base/java.lang=ALL-UNNAMED
finished: Mon Jan 01 10:17:57 UTC 2024
elapsed time (seconds): 4.443
----------configuration:(4/99)----------
Boot Layer
  add modules: java.base           
  add opens:   java.base/java.lang ALL-UNNAMED

----------System.out:(0/0)----------
----------System.err:(169/16014)----------
STARTED    test.java.lang.String.StringRacyConstructor::checkConcatAndIntern 'checkConcatAndIntern()'
SUCCESSFUL test.java.lang.String.StringRacyConstructor::checkConcatAndIntern 'checkConcatAndIntern()'
STARTED    test.java.lang.String.StringRacyConstructor::charSequenceException 'charSequenceException()'
SUCCESSFUL test.java.lang.String.StringRacyConstructor::charSequenceException 'charSequenceException()'
STARTED    test.java.lang.String.StringRacyConstructor::racyString '[1] 01234'
SUCCESSFUL test.java.lang.String.StringRacyConstructor::racyString '[1] 01234'
STARTED    test.java.lang.String.StringRacyConstructor::racyString '[2]  '
SUCCESSFUL test.java.lang.String.StringRacyConstructor::racyString '[2]  '
STARTED    test.java.lang.String.StringRacyConstructor::verifyUTF16CopyBytes 'verifyUTF16CopyBytes()'
SUCCESSFUL test.java.lang.String.StringRacyConstructor::verifyUTF16CopyBytes 'verifyUTF16CopyBytes()'
STARTED    test.java.lang.String.StringRacyConstructor::racyCodePointSurrogates '[1] 01234'
orig: 01234, iffy: ?1234[65584, 49, 50, 51, 52]
SUCCESSFUL test.java.lang.String.StringRacyConstructor::racyCodePointSurrogates '[1] 01234'
STARTED    test.java.lang.String.StringRacyConstructor::racyCodePointSurrogates '[2]  '
java.lang.NullPointerException: Cannot read the array length because "other" is null
	at java.base/java.lang.StringLatin1.equals(StringLatin1.java:210)
	at java.base/java.lang.String.equals(String.java:1905)
	at test.java.lang.String.StringRacyConstructor.racyCodePointSurrogates(StringRacyConstructor.java:187)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:727)
	at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
	at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
	at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestTemplateMethod(TimeoutExtension.java:94)
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
	at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
	at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:217)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:213)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:138)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:68)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask$DefaultDynamicTestExecutor.execute(NodeTestTask.java:226)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask$DefaultDynamicTestExecutor.execute(NodeTestTask.java:204)
	at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.execute(TestTemplateTestDescriptor.java:142)
	at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.lambda$execute$2(TestTemplateTestDescriptor.java:110)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:212)
	at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:194)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:212)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:212)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:212)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:212)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:212)
	at java.base/java.util.AbstractList$RandomAccessSpliterator.forEachRemaining(AbstractList.java:722)
	at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:782)
	at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:291)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:212)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:212)
	at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:1024)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:556)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:546)
	at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:265)
	at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:611)
	at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:291)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:212)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:212)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:212)
	at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1709)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:556)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:546)
	at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:265)
	at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:611)
	at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:291)
	at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1709)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:556)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:546)
	at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:265)
	at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:611)
	at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.execute(TestTemplateTestDescriptor.java:110)
	at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.execute(TestTemplateTestDescriptor.java:44)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1597)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1597)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:147)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:127)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:90)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:55)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:102)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:54)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
	at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
	at com.sun.javatest.regtest.agent.JUnitRunner.runWithJUnitPlatform(JUnitRunner.java:142)
	at com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:95)
	at com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:61)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
	at java.base/java.lang.Thread.run(Thread.java:1570)
FAILED     test.java.lang.String.StringRacyConstructor::racyCodePointSurrogates '[2]  '
STARTED    test.java.lang.String.StringRacyConstructor::racyEmptyString 'racyEmptyString()'
SUCCESSFUL test.java.lang.String.StringRacyConstructor::racyEmptyString 'racyEmptyString()'
STARTED    test.java.lang.String.StringRacyConstructor::checkStringRange 'checkStringRange()'
SUCCESSFUL test.java.lang.String.StringRacyConstructor::checkStringRange 'checkStringRange()'
STARTED    test.java.lang.String.StringRacyConstructor::racyCodePoint '[1] 01234'
SUCCESSFUL test.java.lang.String.StringRacyConstructor::racyCodePoint '[1] 01234'
STARTED    test.java.lang.String.StringRacyConstructor::racyCodePoint '[2]  '
SUCCESSFUL test.java.lang.String.StringRacyConstructor::racyCodePoint '[2]  '
JavaTest Message: JUnit Platform Failure(s): 1

[ JUnit Containers: found 7, started 7, succeeded 7, failed 0, aborted 0, skipped 0]
[ JUnit Tests: found 11, started 11, succeeded 10, failed 1, aborted 0, skipped 0]

java.lang.Exception: JUnit test failure
	at com.sun.javatest.regtest.agent.JUnitRunner.runWithJUnitPlatform(JUnitRunner.java:149)
	at com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:95)
	at com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:61)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
	at java.base/java.lang.Thread.run(Thread.java:1570)

JavaTest Message: Test threw exception: java.lang.Exception: JUnit test failure
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.Exception: JUnit test failure
----------rerun:(48/5950)*----------
Comments
Changeset: 7cd25ed6 Author: Cesar Soares Lucas <cslucas@openjdk.org> Committer: Tobias Hartmann <thartmann@openjdk.org> Date: 2024-02-13 13:50:59 +0000 URL: https://git.openjdk.org/jdk/commit/7cd25ed605469e3946a204b7b18d975c9768f2df
13-02-2024
Deferral Request (JDK 22) JDK-8324688 disabled the feature by default in JDK 22 and it can only be re-enabled with a diagnostic flag.
29-01-2024
A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/17562 Date: 2024-01-24 22:40:59 +0000
24-01-2024
> Well, I missed a case. For the record it was (2d) The JIT might scalar-replace a string, but then generate it onto the heap. (This is for deoptimization, recovery from an uncommon event, previously speculated against.) In that case the JIT generates the string object not by executing code but interpreting debug-info. If that generation process failed to issue a store-store barrier, on a CPU that needed it, and there was no other store-store barrier issued (during the course of deoptimization), then conceivably you might get a race. I think this is unlikely, but I do worry about it from time to time. Every time we make a new clever way to create objects, we potentially create a new bug tail related to initialization races. I just want to point that scalar-replaced String object does not escape (otherwise EA will nor remove it) - no other threads can access it. I am not sure what race can be here. Correction. Object does not escape (and as such eliminated) only in compiled code. It may escape after rematerialization in Interpreter. [~jrose] is right (as always). Consider next: void test(int i) { Test t = new Test(i); if (i == foo()) { // Rare case so C2 generates uncommon trap. Object 't' does not escape from EA POV // since it is referenced only by uncommon trap. It will escape after deoptimization. Test::_t = t; // store into public static field } }
17-01-2024
Note, EA marks object as not-escaped even when it referenced by uncommon trap (where it will be rematerialized). such object can escape after rematerialization during deoptimization (as in these tests). So yes, store-store barrier is needed after we reassigned fields to such object regardless current bug. I filed bug JDK-8324050 to added OrderAccess::storestore(); after we rematerialize objects.
17-01-2024
Right, the issue was extremely intermittent in our testing because it required deoptimization to trigger at the "right point." And the uncommon trap at this point was an unstable-if trap that would only trigger when we (don't) hit a race condition between two threads (see the "until we hit the race condition" comment in the attached Test.java). So it was all dependent on thread scheduling and that's why rr's Chaos Mode, which essentially randomizes thread scheduling, was able to reproduce it.
17-01-2024
Thank you for pinging [~thartmann]. I'll start taking a look into this today.
16-01-2024
Well, I missed a case. For the record it was (2d) The JIT might scalar-replace a string, but then generate it onto the heap. (This is for deoptimization, recovery from an uncommon event, previously speculated against.) In that case the JIT generates the string object not by executing code but interpreting debug-info. If that generation process failed to issue a store-store barrier, on a CPU that needed it, and there was no other store-store barrier issued (during the course of deoptimization), then conceivably you might get a race. I think this is unlikely, but I do worry about it from time to time. Every time we make a new clever way to create objects, we potentially create a new bug tail related to initialization races. So, if a bug looks like a deserialization bug (2a), remember that the JIT sometimes deserializes scalar-replaced objects (2d), from the JIT's own serialized object representations inside debug info. Another similar case of that might be JNI-based object creation (2e). And… apparently it wasn’t a race, it was just bad data in the serialized object representation stashed by the JIT. So the apparent intermittency or platform-specificity were a false signals. The bug was more rare than intermittent? The path that you get to, when the JIT reconstructs an interpreter stack frame from de-optimized code, is called uncommon_trap. I hope my little checklist exercise helps with similar bugs in the future!
16-01-2024
[~cslucas], please have a look.
16-01-2024
I attached a simple test with two scenarios (String and custom class) that reproduces this issue reliably (Reproducer.java): java -XX:CompileCommand=quiet -XX:CompileCommand=compileonly,Reproducer::testString -XX:-TieredCompilation -Xbatch Reproducer.java Exception in thread "main" java.lang.NullPointerException: Cannot read the array length because "this.value" is null at java.base/java.lang.String.length(String.java:1546) at java.base/java.io.Writer.write(Writer.java:278) at java.base/java.io.PrintStream.implWriteln(PrintStream.java:846) at java.base/java.io.PrintStream.writeln(PrintStream.java:826) at java.base/java.io.PrintStream.println(PrintStream.java:1168) at Reproducer.main(Reproducer.java:72) java -XX:CompileCommand=quiet -XX:CompileCommand=compileonly,Reproducer::testMyClass -XX:-TieredCompilation -Xbatch Reproducer.java Exception in thread "main" java.lang.RuntimeException: Test failed, val = 0 at Reproducer.main(Reproducer.java:69) I confirmed that this is a regression of JDK-8287061. ILW = Incorrect rematerialization of scalar replaced objects in C2 (regression in JDK 22), easy to reproduce, -XX:-ReduceAllocationMerges = HML = P2
16-01-2024
Hello John, > In the offending constructor, try setting `this.value` sooner, as soon as the array is constructed, instead of after the setting of `this.coder`. If that hides the bug, then the next question is, should the JIT be doing more at constructor exit time, to force the writes to be more timely? To be clear: Such a minor change might hide the bug, not fix it. Or, to make another gross change, put a “heavy” statement (temporarily, such as a volatile write or memory fence) at the end of the affected constructor, to “encourage” the stores to settle. Again, if that hides the bug, perhaps we are dealing with a race condition for events before and after constructor exit. I think the possibility that this is something related to events before and after constructor exit doesn't seem likely for this test. The test (like you have noted) constructs the String instance "s" and then that "s" is passed to a original.equals(s) call (in the same main thread). However, before even calling the original.equals(s), there's this call in the test: > s.length() != original.length() and the implementation of length() method on String class does this: > return value.length >> coder(); so if this was a race in some events of constructor exit, then it should have failed with a NullPointerException, right here on the length() call, but it hasn't. So it appears that the main thread had seen this "s" instance to have a non-null "value" at least once after the construction completed.
16-01-2024
I was able to reproduce this with rr's Chaos Mode (https://robert.ocallahan.org/2016/02/introducing-rr-chaos-mode.html) and the attached Test.java which prints the address of the broken String object. while rm -r -f /home/tohartma/.local/share/rr/* && rr record -h jdk/build/fastdebug/images/jdk/bin/java -Xmx1g Test.java; do :; done; 0x5a8666ca8 Exception in thread "main" java.lang.NullPointerException: Cannot read the array length because "this.value" is null at java.base/java.lang.String.length(String.java:1546) at java.base/java.io.Writer.write(Writer.java:278) at java.base/java.io.PrintStream.implWriteln(PrintStream.java:846) at java.base/java.io.PrintStream.writeln(PrintStream.java:826) at java.base/java.io.PrintStream.println(PrintStream.java:1168) at Test.racyCodePointSurrogates(Test.java:85) at Test.main(Test.java:96) Debugging with rr shows that it seems to be a problem with deoptimization: (rr) x/x 0x5a8666ca8+20 0x5a8666cbc: 0xb50ccd98 (rr) x/x ((long)0xb50ccd98)<<3 0x5a8666cc0: 0x00000001 [...] Thread 2 hit Hardware watchpoint 1: *0x5a8666cbc Old value = -1163019586 New value = 0 __memset_evex_unaligned_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:239 239 ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S: No such file or directory. (rr) where #0 __memset_evex_unaligned_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:239 #1 0x00002bf84d584d1f in ObjAllocator::initialize(HeapWordImpl**) const () from /scratch/tohartma/jdk-22/fastdebug/lib/server/libjvm.so #2 0x00002bf84d586a87 in MemAllocator::allocate() const () from /scratch/tohartma/jdk-22/fastdebug/lib/server/libjvm.so #3 0x00002bf84d04bbda in InstanceKlass::allocate_instance(JavaThread*) () from /scratch/tohartma/jdk-22/fastdebug/lib/server/libjvm.so #4 0x00002bf84ccebed1 in Deoptimization::realloc_objects(JavaThread*, frame*, RegisterMap*, GrowableArray<ScopeValue*>*, JavaThread*) () from /scratch/tohartma/jdk-22/fastdebug/lib/server/libjvm.so #5 0x00002bf84ccf0404 in rematerialize_objects(JavaThread*, int, CompiledMethod*, frame&, RegisterMap&, GrowableArray<compiledVFrame*>*, bool&) () from /scratch/tohartma/jdk-22/fastdebug/lib/server/libjvm.so #6 0x00002bf84ccf2a7d in Deoptimization::fetch_unroll_info_helper(JavaThread*, int) () from /scratch/tohartma/jdk-22/fastdebug/lib/server/libjvm.so #7 0x00002bf84ccf5e92 in Deoptimization::uncommon_trap(JavaThread*, int, int) () from /scratch/tohartma/jdk-22/fastdebug/lib/server/libjvm.so (rr) c Continuing. 0x5a8666ca8 (rr) x/x 0x5a8666ca8+20 0x5a8666cbc: 0x00000000 We deopt from C2 compiled 'Test::racyStringConstructionCodepointsSurrogates': => 0x2e13849f2a0b: call 0x2e13844e5e20 -> UncommonTrapBlob 0x2e13849f2a10: nopl 0xe000d00(%rax,%rax,1) And the ScopeDesc for that location contains a String with a 'nullptr' value field (which should actually be printed as 'null' - I filed JDK-8323803): ScopeDesc(pc=0x00002e13849f2a10 offset=970): Test::racyStringConstructionCodepointsSurrogates@110 (line 60) reexecute=true Locals - l0: empty - l1: empty - l2: empty - l3: stack[24],oop - l4: empty - l5: merge_obj[708] - l6: empty Expression stack - @0: reg rbp [10],int - @1: 1000000 Objects - 0: R merge_obj[708], selector="stack[8]", candidate_objs=[709, 710] - 1: obj[709], java.lang.String Fields: 0, 0, 0, stack[40],oop - 2: obj[710], java.lang.String Fields: 0, 0, 0, nullptr Line 60 in the test is: if ((s.length() != original.length()) || i > 1_000_000) { This is most likely a regression from JDK-8287061 ([~cslucas]).
16-01-2024
Some general comments on this failure: It looks like the condition `String.value==null` is appearing in some string S that Java test code is working on. And, it is on short strings (`" "`). The null is observed when some other string is compared against it, and the problem manifests on the second argument of `StringLatin1.equals(byte[] value, byte[] other)`. This is probably not related to `@Stable`, even though `String.value` is declared stable. The JIT performs constant folding only on stable field values which are *non-zero*. By design, that avoids bugs where a final variable (like `String.value`) starts out null, gets captured too soon by the JIT, and becomes non-null. A proper implementation of stable values would require language changes, to make a “hard distinction” between objects which are still being formed (“larval objects”) and those which have been permanently frozen (“adult objects”). Valhalla is designing a firmer sense of stability like this, for value objects. In the present bug, the observed null might either have been (1) the original default null stored in every `String.value`, or it might have been (2) patched in later. Starting with the original default null: This null is overwritten with the string’s non-null payload, in the string constructor, always. The only way this null could be visible is if (1a) the constructor itself were to call `StringLatin1.equals(byte[] value, byte[] other)`. Or else, when the constructor returns, there was (1b) a missing `this.value = foo` assignment. Neither of those seem to be the case; the `String.java` code is too well written for obvious bugs like that. There is a third possibility: (1c) A missing memory fence could cause the original null to be visible, for a few nanoseconds after the constructor returns. Specifically, if S was created in some thread T1 but the observation (the `StringLatin1.equals` call) happens in some other thread T2, T2 is prevented from seeing a null only if T1 placed a store-store barrier between the write of `S.value` and the write which publishes S. Somehow the pointer to S would have to cross from T1 to T2, and T2 would use it, while the non-null `S.value` was still crossing the memory fabric to T2, behind the journey of S itself to T2. I don't think this can happen on any X86 chips, because the journey of S begins (in T1) before the journey of `S.value`, and a store buffer (in T1 on X86) preserves that order. (As a basic requirement, the JIT also has to preserve the order as well in the code it makes for T1 to run.) There is no way for T2 to accidentally “scoop” an out-of-order value from the store buffer of T1. There is yet again a fourth way that the larval null value can be read: (1d) If the GC runs during a safepoint inside a string constructor, before `this.value = foo` happens, the GC will witness a null value in that field. It should not take any special action on this null, but if it did, there could be trouble. GC optimizations must not malfunction if they encounter larval strings, or any other kind of larval object. In particular, deduplication must not be attempted on any larval object, because it such an object is temporarily mutable, and so may change state before it is promoted by adult (by constructor return). What about case (2), patching in the null after the string S is created? That could happen in several ways: Perhaps (2a) the string was created deliberately in a partially constructed form by deserialization logic, and patched later on. Or (2b) errant reflection code clobbered the field. There is some odd-looking reflection code in `StringRacyConstructor.java`, but no calls to `Field::set` that could set the value field to null. Or (2c) a GC bug might patch the field, although it is hard to imagine a bug which has been waiting all this time just for this test case. Out of all of the above possibilities, I think a race condition seems most likely, simply because of the sharp dependency on hardware and software platform. In the offending constructor, try setting `this.value` sooner, as soon as the array is constructed, instead of after the setting of `this.coder`. If that hides the bug, then the next question is, should the JIT be doing more at constructor exit time, to force the writes to be more timely? To be clear: Such a minor change might hide the bug, not fix it. Or, to make another gross change, put a “heavy” statement (temporarily, such as a volatile write or memory fence) at the end of the affected constructor, to “encourage” the stores to settle. Again, if that hides the bug, perhaps we are dealing with a race condition for events before and after constructor exit.
15-01-2024
The new StringRacyConstructor test creates about 1 million nearly identical strings using `java.lang.String(int[], int offset, int count)`. Its implementation does most of its work using byte arrays. The final step is to set the coder and value fields of the new string. The coder field is computed from the length of the value byte array. A null value would have been detected at that point. Puzzling...
11-01-2024
Thanks for linking in these two failures. The last two failures indicate that this is not a ZGC issue.
10-01-2024
Here's a log file snippet from the jdk-22+31-2303-tier5 sighting: java/lang/String/StringRacyConstructor.java #section:junit ----------messages:(7/444)---------- command: junit -XX:+CompactStrings test.java.lang.String.StringRacyConstructor reason: User specified action: run junit/othervm -XX:+CompactStrings test.java.lang.String.StringRacyConstructor started: Wed Jan 10 07:25:34 UTC 2024 Mode: othervm [/othervm specified] Additional options from @modules: --add-modules java.base --add-opens java.base/java.lang=ALL-UNNAMED finished: Wed Jan 10 07:25:40 UTC 2024 elapsed time (seconds): 5.855 ----------configuration:(4/99)---------- Boot Layer add modules: java.base add opens: java.base/java.lang ALL-UNNAMED ----------System.out:(17/1030)*---------- # # A fatal error has been detected by the Java Runtime Environment: # # Internal Error (c:\\sb\\prod\\1704841336\\workspace\\open\\src\\hotspot\\cpu\\x86\\macroAssembler_x86.cpp:831), pid=9884, tid=23616 # fatal error: DEBUG MESSAGE: unexpected null in intrinsic # # JRE version: Java(TM) SE Runtime Environment (22.0+31) (fastdebug build 22-ea+31-2303) # Java VM: Java HotSpot(TM) 64-Bit Server VM (fastdebug 22-ea+31-2303, mixed mode, sharing, tiered, compressed oops, compressed class ptrs, g1 gc, windows-amd64) # Core dump will be written. Default location: C:\\sb\\prod\\1704870362\\testoutput\\test-support\\jtreg_open_test_jdk_tier1\\scratch\\2\\hs_err_pid9884.mdmp # # An error report file with more information is saved as: # C:\\sb\\prod\\1704870362\\testoutput\\test-support\\jtreg_open_test_jdk_tier1\\scratch\\2\\hs_err_pid9884.log [4.805s][warning][os] Loading hsdis library failed # # If you would like to submit a bug report, please visit: # https://bugreport.java.com/bugreport/crash.jsp # ----------System.err:(13/1209)---------- STARTED test.java.lang.String.StringRacyConstructor::checkConcatAndIntern 'checkConcatAndIntern()' SUCCESSFUL test.java.lang.String.StringRacyConstructor::checkConcatAndIntern 'checkConcatAndIntern()' STARTED test.java.lang.String.StringRacyConstructor::charSequenceException 'charSequenceException()' SUCCESSFUL test.java.lang.String.StringRacyConstructor::charSequenceException 'charSequenceException()' STARTED test.java.lang.String.StringRacyConstructor::racyString '[1] 01234' SUCCESSFUL test.java.lang.String.StringRacyConstructor::racyString '[1] 01234' STARTED test.java.lang.String.StringRacyConstructor::racyString '[2] ' SUCCESSFUL test.java.lang.String.StringRacyConstructor::racyString '[2] ' STARTED test.java.lang.String.StringRacyConstructor::verifyUTF16CopyBytes 'verifyUTF16CopyBytes()' SUCCESSFUL test.java.lang.String.StringRacyConstructor::verifyUTF16CopyBytes 'verifyUTF16CopyBytes()' STARTED test.java.lang.String.StringRacyConstructor::racyCodePointSurrogates '[1] 01234' SUCCESSFUL test.java.lang.String.StringRacyConstructor::racyCodePointSurrogates '[1] 01234' STARTED test.java.lang.String.StringRacyConstructor::racyCodePointSurrogates '[2] ' ----------rerun:(50/6230)*---------- <snip> result: Failed. Unexpected exit from test [exit code: 1] Here's the crashing thread's stack: --------------- T H R E A D --------------- Current thread (0x000002887c1f8300): JavaThread "ForkJoinPool-1-worker-1" daemon [_thread_in_Java, id=23616, stack(0x000000a3bce00000,0x000000a3bcf00000) (1024K)] Stack: [0x000000a3bce00000,0x000000a3bcf00000] Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code) V [jvm.dll+0xc94581] os::win32::platform_print_native_stack+0x101 (os_windows_x86.cpp:236) V [jvm.dll+0xf36fcb] VMError::report+0x149b (vmError.cpp:1005) V [jvm.dll+0xf3961e] VMError::report_and_die+0x80e (vmError.cpp:1834) V [jvm.dll+0x5549ae] report_fatal+0x7e (debug.cpp:212) V [jvm.dll+0xb640fc] MacroAssembler::debug64+0xcc (macroAssembler_x86.cpp:831) C 0x000002882f2b369e (no source info available) I think this is another variation of the original failure mode. If not, let me know and I'll move these two comments to a new bug.
10-01-2024
This test was added with: commit 155abc576a0212932825485380d4e2a9c7dd2fdc Author: Roger Riggs <rriggs@openjdk.org> Date: Mon Dec 4 18:28:59 2023 +0000 8311906: Improve robustness of String constructors with mutable array inputs
09-01-2024
The failing code looks like this: ``` public boolean equals(Object anObject) { if (this == anObject) { return true; } return (anObject instanceof String aString) && (!COMPACT_STRINGS || this.coder == aString.coder) && StringLatin1.equals(value, aString.value); } ``` where aString.value is passed down as null to StringLatin1.equals.
05-01-2024