JDK-8200365 : TestOptionsWithRanges.java of '-XX:TLABWasteTargetPercent=100' fails intermittently
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 11,12
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: linux
  • CPU: x86_64
  • Submitted: 2018-03-28
  • Updated: 2023-09-12
  • Resolved: 2018-08-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 11 JDK 12 JDK 8
11.0.5-oracleFixed 12 b07Fixed 8u401Fixed
Related Reports
Duplicate :  
Relates :  
Relates :  
Description
While testing the fix for JDK-8199813 in Mach5, the following
test failed once:

runtime/CommandLine/OptionsValidation/TestOptionsWithRanges.java

Here is a snippet of the .jtr file:

----------System.err:(24/1918)----------
TEST FAILED: Error processing option TLABWasteTargetPercent with valid value '-server -XX:+UseSerialGC -XX:TLABWasteTargetPercent=100'! JVM exited with unexpected error code = 139 [0x8B]
stdout content[Error occurred during initialization of VM
GC triggered before VM initialization completed. Try increasing NewSize, current value 157M.
]
stderr content[]

java.lang.RuntimeException: 1 tests failed! (Error processing option TLABWasteTargetPercent with valid value '-server -XX:+UseSerialGC -XX:TLABWasteTargetPercent=100'! JVM exited with unexpected error code = 139 [0x8B])
: expected 1 to equal 0
	at jdk.test.lib.Asserts.fail(Asserts.java:594)
	at jdk.test.lib.Asserts.assertEquals(Asserts.java:205)
	at jdk.test.lib.Asserts.assertEQ(Asserts.java:178)
	at TestOptionsWithRanges.main(TestOptionsWithRanges.java:138)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:115)
	at java.base/java.lang.Thread.run(Thread.java:842)

JavaTest Message: Test threw exception: java.lang.RuntimeException: 1 tests failed! (Error processing option TLABWasteTargetPercent with valid value '-server -XX:+UseSerialGC -XX:TLABWasteTargetPercent=100'! JVM exited with unexpected error code = 139 [0x8B])
: expected 1 to equal 0
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.RuntimeException: 1 tests failed! (Error processing option TLABWasteTargetPercent with valid value '-server -XX:+UseSerialGC -XX:TLABWasteTargetPercent=100'! JVM exited with unexpected error code = 139 [0x8B]) : expected 1 to equal 0


This error message on stdout stands out to me:

Error occurred during initialization of VM
GC triggered before VM initialization completed. Try increasing NewSize, current value 157M.

Also, I looked for an hs_err_pid file, but did not find one.
Comments
Fix Request: Requesting backport of this test fix to JDK11 updates to match up with Oracle. Patch applies cleanly. Fix will be tested in SAP's test system.
18-06-2019

URL: http://hg.openjdk.java.net/jdk/jdk/rev/be775229d3b3 User: tschatzl Date: 2018-08-13 10:24:41 +0000
13-08-2018

Okay, sorry for the misunderstanding. Yes, the failure occurs at initialization: the TLABWastePercent value (any >= 26) causes the first Java thread to allocate a huge TLAB, not enough for same-sized TLABs of additional threads, which causes an early GC the VM does not support. See the analysis at https://bugs.openjdk.java.net/browse/JDK-8200365?focusedCommentId=14197318&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-14197318 for more information.
09-08-2018

java FLAGS -version as per the output. My reference to "-version" was just to clarify that no actual test needed to be run - sorry for the confusion.
09-08-2018

@dholmes: if the program fails with "java -version" then this is most likely a different bug: this one is explicitly about TLABWasteTargetPercent and only affects Serial, CMS and Parallel GC. If the VM fails just with "java -version", the VM uses G1 which is not affected by this issue. Please open another bug; preferably with output of -XX:+PrintFlagsFinal.
09-08-2018

This is a recurring failure, presumably dependent on the machine memory size. It fails for me with a fastdebug build just doing "java -version" > ../../../../build/linux-x64/images/jdk/bin/java -XX:+UseConcMarkSweepGC -XX:TLABWasteTargetPercent=100 -version Java HotSpot(TM) 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release. Error occurred during initialization of VM GC triggered before VM initialization completed. Try increasing NewSize, current value 682M.
09-08-2018

Resetting for re-triage
23-07-2018

This bug is now happening in various CI jobs and not just with my experimental Mach5 jobs so I'm clearing myself as the RE.
23-07-2018

The flag causes the initial TLAB sizes to be extremely large (as probably expected when you specify this flag) for non-G1 collectors, causing GCs during initialization. G1 works only because it limits the TLAB size to half a region. Here's some relevant code: void ThreadLocalAllocBuffer::startup_initialization() { // Assuming each thread's active tlab is, on average, // 1/2 full at a GC _target_refills = 100 / (2 * TLABWasteTargetPercent); _target_refills = MAX2(_target_refills, (unsigned)1U); [...] I.e. _target_refills is 1 at that point, which causes very large TLABs at startup. The fake initial sample data we use for startup is derived from _target_refills as divisor, which is very small at that point, causing very large suggested TLABs. The reason why the crossing value is 26 where it starts to fail is because at that point _target_refills gets 1.
18-07-2018

Closing this bug as "Cannot Reproduce" since the failure mode has never been seen outside of some Adhoc Mach5 jobs with experimental Thread-SMR bits.
18-06-2018

[~dcubed]: has there been any progress on this? If not, would you mind closing it? We would not want to spend time on fixing some bug with unknown experimental changes.
18-06-2018

Changing from P2 -> P4 since this failure mode has only been seen in adhoc Mach5 jobs with experimental bits.
17-04-2018

I've assigned myself the bug so that I can investigate it more. The specific failure mode (SIGSEGV during reporting of "Error occurred during initialization of VM GC triggered before VM initialization completed. Try increasing NewSize, current value ..." may be something unique to Thread-SMR.
17-04-2018

[~dcubed]: what do you mean with "I'm taking this back"? Do you think there is no issue, or one of the comments. If it is not an issue, please close the CR appropriately.
16-04-2018

Only happens with my experimental code so I'm taking this back.
11-04-2018

Same test, different option, same failure mode. ----------System.err:(24/1842)---------- TEST FAILED: Error processing option TLABSize with valid value '-server -XX:+UseParallelGC -XX:TLABSize=4294967296'! JVM exited with unexpected error code = 139 [0x8B] stdout content[Error occurred during initialization of VM GC triggered before VM initialization completed. Try increasing NewSize, current value 157M. ] stderr content[] java.lang.RuntimeException: 1 tests failed! (Error processing option TLABSize with valid value '-server -XX:+UseParallelGC -XX:TLABSize=4294967296'! JVM exited with unexpected error code = 139 [0x8B]) : expected 1 to equal 0 at jdk.test.lib.Asserts.fail(Asserts.java:594) at jdk.test.lib.Asserts.assertEquals(Asserts.java:205) at jdk.test.lib.Asserts.assertEQ(Asserts.java:178) at TestOptionsWithRanges.main(TestOptionsWithRanges.java:138) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:569) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:115) at java.base/java.lang.Thread.run(Thread.java:841) JavaTest Message: Test threw exception: java.lang.RuntimeException: 1 tests failed! (Error processing option TLABSize with valid value '-server -XX:+UseParallelGC -XX:TLABSize=4294967296'! JVM exited with unexpected error code = 139 [0x8B]) : expected 1 to equal 0 JavaTest Message: shutting down test STATUS:Failed.`main' threw exception: java.lang.RuntimeException: 1 tests failed! (Error processing option TLABSize with valid value '-server -XX:+UseParallelGC -XX:TLABSize=4294967296'! JVM exited with unexpected error code = 139 [0x8B]) : expected 1 to equal 0 So it looks like the "Error occurred during initialization of VM GC triggered before VM initialization completed. Try increasing NewSize, current value 157M." failure mode might be the key here...
05-04-2018

There's little point comparing 8 and 11 here. As the error says a GC was triggered during VM initialization. This can happen in 11, but not 8 (for example) if class initialization involves a lot more heap usage during VM initialization (eg. the new string concat behaviour). I'm not completely clear on the practical impact of this flag but if it effectively reduces the amount of available memory then we can hit this problem any time something in the class initialization process increases its memory use. So I would say this is a test bug because there is absolutely no guarantee that this flag can be modified across its range, successfully, whilst leaving all other flags constant. It will be intermittent because the amount of Java heap used during VM initialization will not be constant across different runs - and there may be multi-threading issues involved as well.
04-04-2018

This is not a test bug, as it passes in jdk8: JDK8u Results =========== >>> G1GC TLABWasteTargetPercent=1 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) >>> G1GC TLABWasteTargetPercent=25 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) >>> G1GC TLABWasteTargetPercent=26 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) >>> G1GC TLABWasteTargetPercent=100 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) ==================================== >>> UseParallelGC TLABWasteTargetPercent=1 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) >>> UseParallelGC TLABWasteTargetPercent=25 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) >>> UseParallelGC TLABWasteTargetPercent=26 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) >>> UseParallelGC TLABWasteTargetPercent=100 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) ==================================== >>> UseParallelOldGC TLABWasteTargetPercent=1 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) >>> UseParallelOldGC TLABWasteTargetPercent=25 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) >>> UseParallelOldGC TLABWasteTargetPercent=26 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) >>> UseParallelOldGC TLABWasteTargetPercent=100 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) ==================================== >>> UseSerialGC TLABWasteTargetPercent=1 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) >>> UseSerialGC TLABWasteTargetPercent=25 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) >>> UseSerialGC TLABWasteTargetPercent=26 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) >>> UseSerialGC TLABWasteTargetPercent=100 java version "1.8.0_162-ea-fastdebug" Java(TM) SE Runtime Environment (build 1.8.0_162-ea-fastdebug-b03) Java HotSpot(TM) 64-Bit Server VM (build 25.162-b03-fastdebug, mixed mode) JDK11 Results =========== >>> G1GC TLABWasteTargetPercent=1 java version "11-internal" 2018-09-18 Java(TM) SE Runtime Environment 18.9 (fastdebug build 11-internal+0-2018-04-03-1542151.gctriant.jdk11-hs) Java HotSpot(TM) 64-Bit Server VM 18.9 (fastdebug build 11-internal+0-2018-04-03-1542151.gctriant.jdk11-hs, mixed mode) >>> G1GC TLABWasteTargetPercent=25 java version "11-internal" 2018-09-18 Java(TM) SE Runtime Environment 18.9 (fastdebug build 11-internal+0-2018-04-03-1542151.gctriant.jdk11-hs) Java HotSpot(TM) 64-Bit Server VM 18.9 (fastdebug build 11-internal+0-2018-04-03-1542151.gctriant.jdk11-hs, mixed mode) >>> G1GC TLABWasteTargetPercent=26 java version "11-internal" 2018-09-18 Java(TM) SE Runtime Environment 18.9 (fastdebug build 11-internal+0-2018-04-03-1542151.gctriant.jdk11-hs) Java HotSpot(TM) 64-Bit Server VM 18.9 (fastdebug build 11-internal+0-2018-04-03-1542151.gctriant.jdk11-hs, mixed mode) >>> G1GC TLABWasteTargetPercent=100 java version "11-internal" 2018-09-18 Java(TM) SE Runtime Environment 18.9 (fastdebug build 11-internal+0-2018-04-03-1542151.gctriant.jdk11-hs) Java HotSpot(TM) 64-Bit Server VM 18.9 (fastdebug build 11-internal+0-2018-04-03-1542151.gctriant.jdk11-hs, mixed mode) ==================================== >>> UseParallelGC TLABWasteTargetPercent=1 java version "11-internal" 2018-09-18 Java(TM) SE Runtime Environment 18.9 (fastdebug build 11-internal+0-2018-04-03-1542151.gctriant.jdk11-hs) Java HotSpot(TM) 64-Bit Server VM 18.9 (fastdebug build 11-internal+0-2018-04-03-1542151.gctriant.jdk11-hs, mixed mode) >>> UseParallelGC TLABWasteTargetPercent=25 java version "11-internal" 2018-09-18 Java(TM) SE Runtime Environment 18.9 (fastdebug build 11-internal+0-2018-04-03-1542151.gctriant.jdk11-hs) Java HotSpot(TM) 64-Bit Server VM 18.9 (fastdebug build 11-internal+0-2018-04-03-1542151.gctriant.jdk11-hs, mixed mode) >>> UseParallelGC TLABWasteTargetPercent=26 Error occurred during initialization of VM GC triggered before VM initialization completed. Try increasing NewSize, current value 682M. Similar failures for JDK11 and JDK9 GA with -XX:+UseParallelOldGC and -XX:+UseSerialGC.
04-04-2018

Tested from the command line with jdk11 and with jdk9. Values of TLABWasteTargetPercent>25 fail for both: Error occurred during initialization of VM GC triggered before VM initialization completed. Try increasing NewSize, current value 682M. >>> TLABWasteTargetPercent=1 java version "11-internal" 2018-09-18 Java(TM) SE Runtime Environment 18.9 (fastdebug build 11-internal+0-2018-03-29-1844132.gctriant.jdk11-hs) Java HotSpot(TM) 64-Bit Server VM 18.9 (fastdebug build 11-internal+0-2018-03-29-1844132.gctriant.jdk11-hs, mixed mode) >>> TLABWasteTargetPercent=2 java version "11-internal" 2018-09-18 Java(TM) SE Runtime Environment 18.9 (fastdebug build 11-internal+0-2018-03-29-1844132.gctriant.jdk11-hs) Java HotSpot(TM) 64-Bit Server VM 18.9 (fastdebug build 11-internal+0-2018-03-29-1844132.gctriant.jdk11-hs, mixed mode) >>> TLABWasteTargetPercent=3 java version "11-internal" 2018-09-18 Java(TM) SE Runtime Environment 18.9 (fastdebug build 11-internal+0-2018-03-29-1844132.gctriant.jdk11-hs) Java HotSpot(TM) 64-Bit Server VM 18.9 (fastdebug build 11-internal+0-2018-03-29-1844132.gctriant.jdk11-hs, mixed mode) . . . >>> TLABWasteTargetPercent=25 java version "11-internal" 2018-09-18 Java(TM) SE Runtime Environment 18.9 (fastdebug build 11-internal+0-2018-03-29-1844132.gctriant.jdk11-hs) Java HotSpot(TM) 64-Bit Server VM 18.9 (fastdebug build 11-internal+0-2018-03-29-1844132.gctriant.jdk11-hs, mixed mode) >>> TLABWasteTargetPercent=26 Error occurred during initialization of VM GC triggered before VM initialization completed. Try increasing NewSize, current value 682M. >>> TLABWasteTargetPercent=1 java version "9" Java(TM) SE Runtime Environment (fastdebug build 9+181) Java HotSpot(TM) 64-Bit Server VM (fastdebug build 9+181, mixed mode) >>> TLABWasteTargetPercent=2 java version "9" Java(TM) SE Runtime Environment (fastdebug build 9+181) Java HotSpot(TM) 64-Bit Server VM (fastdebug build 9+181, mixed mode) >>> TLABWasteTargetPercent=3 java version "9" Java(TM) SE Runtime Environment (fastdebug build 9+181) Java HotSpot(TM) 64-Bit Server VM (fastdebug build 9+181, mixed mode) . . . >>> TLABWasteTargetPercent=25 java version "9" Java(TM) SE Runtime Environment (fastdebug build 9+181) Java HotSpot(TM) 64-Bit Server VM (fastdebug build 9+181, mixed mode) >>> TLABWasteTargetPercent=26 Error occurred during initialization of VM GC triggered before VM initialization completed. Try increasing NewSize, current value 682M.
02-04-2018

[~dcubed], will you provide logs (or links)?
02-04-2018