JDK-8058568 : GC cleanup phase can cause G1 skipping a System.gc()
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 8u40,9
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2014-09-16
  • Updated: 2015-06-03
  • Resolved: 2014-10-21
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 8 JDK 9
8u40Fixed 9 b38Fixed
Description
gc/g1/TestHumongousShrinkHeap.java failed in PIT:

----------messages:(3/338)----------
command: main -XX:MinHeapFreeRatio=10 -XX:MaxHeapFreeRatio=12 -XX:+UseG1GC -XX:G1HeapRegionSize=1M -verbose:gc TestHumongousShrinkHeap
reason: User specified action: run main/othervm -XX:MinHeapFreeRatio=10 -XX:MaxHeapFreeRatio=12 -XX:+UseG1GC -XX:G1HeapRegionSize=1M -verbose:gc TestHumongousShrinkHeap 
elapsed time (seconds): 0.739
----------System.out:(22/1712)----------
Running with 15.0 MiB max heap size. Will allocate humongous object of 921.6 KiB size 1 times.
[Full GC (System.gc())  1024K->546K(6144K), 0.0052482 secs]
[init                    ] init: 16.0 MiB, used: 546.7 KiB, comm: 6.0 MiB, freeRatio ~= 91.1%
[allocate #1             ] init: 16.0 MiB, used: 1.4 MiB, comm: 6.0 MiB, freeRatio ~= 76.1%
[GC pause (G1 Humongous Allocation) (young) (initial-mark) 1591K->1500K(6144K), 0.0007090 secs]
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0001866 secs]
[GC concurrent-mark-start]
[GC concurrent-mark-end, 0.0012979 secs]
[allocate #2             ] init: 16.0 MiB, used: 2.4 MiB, comm: 6.0 MiB, freeRatio ~= 60.6%
[GC remark, 0.0018933 secs]
[allocate #3             ] init: 16.0 MiB, used: 3.3 MiB, comm: 6.0 MiB, freeRatio ~= 45.6%
[allocate #4             ] init: 16.0 MiB, used: 4.2 MiB, comm: 7.0 MiB, freeRatio ~= 40.5%
[allocate #5             ] init: 16.0 MiB, used: 5.1 MiB, comm: 8.0 MiB, freeRatio ~= 36.7%
[allocate #6             ] init: 16.0 MiB, used: 6.0 MiB, comm: 9.0 MiB, freeRatio ~= 33.7%
[allocate #7             ] init: 16.0 MiB, used: 6.9 MiB, comm: 10.0 MiB, freeRatio ~= 31.3%
[allocate #8             ] init: 16.0 MiB, used: 7.8 MiB, comm: 11.0 MiB, freeRatio ~= 29.4%
[allocate #9             ] init: 16.0 MiB, used: 8.7 MiB, comm: 12.0 MiB, freeRatio ~= 27.8%
[allocate #10            ] init: 16.0 MiB, used: 9.6 MiB, comm: 13.0 MiB, freeRatio ~= 26.4%
[allocated               ] init: 16.0 MiB, used: 9.6 MiB, comm: 13.0 MiB, freeRatio ~= 26.4%
[GC cleanup 9897K->9897K(13M), 0.0002581 secs]
[free                    ] init: 16.0 MiB, used: 9.6 MiB, comm: 13.0 MiB, freeRatio ~= 26.4%
----------System.err:(21/1378)----------
java.lang.RuntimeException: committed free heap size is not less than committed full heap size, heap hasn't been shrunk?
MinHeapFreeRatio = 10
MaxHeapFreeRatio = 12
	at com.oracle.java.testlibrary.Asserts.error(Asserts.java:450)
	at com.oracle.java.testlibrary.Asserts.assertTrue(Asserts.java:377)
	at com.oracle.java.testlibrary.Asserts.assertLessThan(Asserts.java:84)
	at TestHumongousShrinkHeap.test(TestHumongousShrinkHeap.java:77)
	at TestHumongousShrinkHeap.main(TestHumongousShrinkHeap.java:62)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:483)
	at com.sun.javatest.regtest.MainWrapper$MainThread.run(MainWrapper.java:94)
	at java.lang.Thread.run(Thread.java:745)
Comments
We've run into this issue in: https://bugs.openjdk.java.net/browse/JDK-8060237 And I've tried the proposed solution of setting _full to true but also changing the call to the VM_G1CollectFull constructor to include the actual full_gc_count instead of the currently passed _old_marking_cycles_started. From what I can see the G1 FullGC code doesn't use the full_gc_count_before to anything else than the skip_operation method which would benefit from this change. I will create a build and start testing it.
17-10-2014
Actually the previously suggested fix does not help at all because skip_operation will always compare the passed full_gc_count_before to total_full_collections() in this case. Which is not comparing the right things. Also, it looks as if any young gc (gc cleanup counts as young gc pause) can make a System.gc() skip.
17-09-2014
The problem seems to be that G1 may skip system gcs that were scheduled just after the gc cleanup phase, but before the gc cleanup phase already started. A potential fix would be to change line 64 in vm_operations_g1.hpp from - : VM_GC_Operation(gc_count_before, cause, full_gc_count_before) { } to + : VM_GC_Operation(gc_count_before, cause, full_gc_count_before, true) { }
17-09-2014
Also check if reproducable in 9. Does not seem to be specific to 8u40. If so, change fix version to 9 and backport
17-09-2014
ILW: I: medium -> test failure L: medium -> only win32 W: high -> none -> P3
17-09-2014
The output is suspiciously missing a [Full GC (System.gc()) xxxK->yyyK(zzzzK), aaa secs] line before the [free ] line.
17-09-2014