JDK-8057586 : Explicit GC ignored if GCLocker is active
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Priority: P5
  • Status: Open
  • Resolution: Unresolved
  • Submitted: 2014-09-04
  • Updated: 2022-05-17
Related Reports
Relates :  
JDK-8057573 - CMSScavengeBeforeRemark ignored if GCLocker is active
Relates :  
JDK-8048556 - Unnecessary GCLocker-initiated young GCs
Description
When a System.gc() is called, the VM operation is scheduled with no synchronization with the GCLocker and, in some cases, the Full GC immediately aborts if the GCLocker is active.

Even though the code path is different, the cause is similar to JDK-8057573.

I have reproduced this with both ParallelGC and CMS.
Comments
ilw: impact: low -> causes young gc with non-full eden instead of full gc likelihood: medium -> lots of gc locker activity workaround: high -> fix application gc locker use -> P5
05-09-2014
This can be reproduced with the same test posted on JDK-8057573 (JNICriticalStressTest3). Run it this way: java -XX:+UseParallelOldGC -Xms3g -Xmx3g -Xmn2g -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+PrintHeapAtGC JNICriticalStressTest3 300 4 1 I attached example output from ParallelGC (output.ps.system-gc). System.gc() was called 59 times (look for the "SYSTEM_GC BEFORE / AFTER" output), but the log only shows 12 Full GCs. Here's the output from a Full GC that did not happen: SYSTEM_GC BEFORE SYSTEM_GC AFTER {Heap before GC invocations=89 (full 0): PSYoungGen total 2073088K, used 720665K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000) eden space 2049024K, 34% used [0x0000000740000000,0x000000076ab2a0e8,0x00000007bd100000) from space 24064K, 87% used [0x00000007be880000,0x00000007bfd1c6e0,0x00000007c0000000) to space 24064K, 0% used [0x00000007bd100000,0x00000007bd100000,0x00000007be880000) ParOldGen total 1048576K, used 84032K [0x0000000700000000, 0x0000000740000000, 0x0000000740000000) object space 1048576K, 8% used [0x0000000700000000,0x0000000705210210,0x0000000740000000) Metaspace used 2783K, capacity 4496K, committed 4864K, reserved 1056768K class space used 293K, capacity 388K, committed 512K, reserved 1048576K 30.219: #88: [GC (GCLocker Initiated GC) [PSYoungGen: 720665K->7140K(2056192K)] 804698K->91437K(3104768K), 0.0049870 secs] [Times: user=0.01 sys=0.00 real=0.00 secs] Heap after GC invocations=89 (full 0): PSYoungGen total 2056192K, used 7140K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000) eden space 2049024K, 0% used [0x0000000740000000,0x0000000740000000,0x00000007bd100000) from space 7168K, 99% used [0x00000007bd100000,0x00000007bd7f9230,0x00000007bd800000) to space 25600K, 0% used [0x00000007be700000,0x00000007be700000,0x00000007c0000000) ParOldGen total 1048576K, used 84296K [0x0000000700000000, 0x0000000740000000, 0x0000000740000000) object space 1048576K, 8% used [0x0000000700000000,0x0000000705252240,0x0000000740000000) Metaspace used 2783K, capacity 4496K, committed 4864K, reserved 1056768K class space used 293K, capacity 388K, committed 512K, reserved 1048576K } Note that instead of the Full GC, a GCLocker-initiated young GC happened with a non-full eden. This looks similar to JDK-8048556 but the cause is different. The Full GC checks whether the GCLocker is active with check_active_before_gc() which has the side-effect of telling the GCLocker to actually schedule a GC as it's normally called when the eden is full.
04-09-2014