JDK-8298215 : gc/g1/TestVerifyGCType.java failed with "Missing expected verification pattern Verifying After GC for: Pause Young (Prepare Mixed): expected true, was false"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 20,21
  • Priority: P2
  • Status: Resolved
  • Resolution: Fixed
  • OS: linux,os_x
  • CPU: x86_64,aarch64
  • Submitted: 2022-12-06
  • Updated: 2023-01-03
  • Resolved: 2022-12-20
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 20 JDK 21
20 b29Fixed 21Fixed
Related Reports
Relates :  
JDK-8298702 - Wrong parameter name comment in G1Policy::revise_young_list_target_length
Relates :  
JDK-8297186 - G1 triggers unnecessary full GCs when heap utilization is low
Sub Tasks
JDK-8298888 :  
ProblemList gc/g1/TestVerifyGCType.java on linux and macosx - Resolved
Description
The following test failed in the JDK20 CI:

gc/g1/TestVerifyGCType.java

Here's a snippet from the log file:

----------System.err:(15/939)----------
java.lang.RuntimeException: Missing expected verification pattern Verifying After GC for: Pause Young (Prepare Mixed): expected true, was false
	at jdk.test.lib.Asserts.fail(Asserts.java:594)
	at jdk.test.lib.Asserts.assertTrue(Asserts.java:486)
	at gc.g1.TestVerifyGCType.verifyType(TestVerifyGCType.java:202)
	at gc.g1.TestVerifyGCType.verifyCollection(TestVerifyGCType.java:197)
	at gc.g1.TestVerifyGCType.testYoungEvacFail(TestVerifyGCType.java:135)
	at gc.g1.TestVerifyGCType.main(TestVerifyGCType.java:57)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
	at java.base/java.lang.Thread.run(Thread.java:1599)

JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test

result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Missing expected verification pattern Verifying After GC for: Pause Young (Prepare Mixed): expected true, was false

Starting this as a P2 since this is Tier1 failure.
Comments
Changeset: ea40f299 Author: Kim Barrett <kbarrett@openjdk.org> Date: 2022-12-20 00:13:25 +0000 URL: https://git.openjdk.org/jdk20/commit/ea40f299397f19f1bbedd4eeb4d24802a709a912
20-12-2022
A pull request was submitted for review. URL: https://git.openjdk.org/jdk20/pull/52 Date: 2022-12-18 22:42:11 +0000
18-12-2022
The problem is a related to the policy change from JDK-8297186. The test is failing because there isn't a verification step at the end of the "Prepare Mixed" collection when the test is only requesting verification after an evacuation failure. This is happening because there wasn't an evacuation failure. There wasn't an evacuation failure because the mutator didn't allocate anything before triggering another GC. The GC set the young length to include an eden regions. However, we now (as of JDK-8137022) revise the young length almost immediately after coming out of the GC, and JDK-8297186 allows there to be no eden regions in that case. So we revise the young length to have no eden regions, then allocate and trigger a GC. That GC doesn't have anything to evacuate, so doesn't have any evacuation failures. And so doesn't do the verification step, causing the test to fail. This situation seems to very intermittent. However, with my proposed changes for JDK-8293824 (https://github.com/openjdk/jdk/pull/11435) this failure becomes very consistent. This can be fixed by ensuring the desired young length always includes at least one eden region, regardless of whether the update is occurring at the end of a GC or during the mutator phase.
17-12-2022
The failure seems to be pretty rare. Only 3 occurrences in Oracle's CI (20/21) so far (1 week since the first occurrence). I've run the test 700 times each on linux-x64 and linux-aarch64 without any failures. Not sure what might have triggered it to start failing, as the obviously relevant code seems to have been stable for a while. One possibility is a subtle effect of JDK-8297186, which was pushed a few hours before the first CI occurrence. The failures I have all look the same, failing with -XX:VerifyGCAfter=young-evac-fail. It turns out my in-development changes to fix JDK-8293824 make this test fail pretty reliably. I changed the output from a failure in the verifyType helper to include the log data, to get more information about what might be going wrong. It looks like what is happening is that after the concurrent cycle completes there is an "ordinary" young GC (not triggered by the test program via WhiteBox) that takes the "Prepare Mixed" slot, and this young GC doesn't have any evacuation failures. Because it doesn't have any evacuation failures (even though command line arguments try to ensure all young GCs will have some), it doesn't print the expected verification log message for that GC, failing the test. Not sure yet why this unrequested GC doesn't produce any evacuation failures.
14-12-2022
Spotted in my macosx-aarch64 stress run with jdk-20+27 bits: $ unzip -l jdk-20+27_macosx-aarch64.8298215.zip Archive: jdk-20+27_macosx-aarch64.8298215.zip Length Date Time Name --------- ---------- ----- ---- 40104 12-11-2022 10:47 jdk-20+27_3/failures.macosx-aarch64/TestVerifyGCType.jtr.fastdebug --------- ------- 40104 1 file
13-12-2022