JDK-8029631 : CollectionUsageThreshold.java fails with -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Priority: P4
  • Status: Closed
  • Resolution: Not an Issue
  • Submitted: 2013-12-05
  • Updated: 2016-08-23
  • Resolved: 2013-12-05
Related Reports
Relates :  
Relates :  
Relates :  
Description
During the review of JDK-7067973 in which the test was fixed to ensure the old gen is non-empty so that System.gc() will cause a GC notification that the test is counting on. However, the test hangs on windows jdk8-b117 when running with  -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent (see log below).

The bug is filed to understand better the hotspot implementation of System.gc() with G1 and CMS with and without -XX:+ExplicitGCInvokesConcurrent.  Thus determine if this is a test bug or a bug in the hotspot GC implementation.

It's unclear what the effect of -XX:+ExplicitGCInvokesConcurrent (the default is disabled).

Specially, there is a G1 old gen.  Is this the same as:
 garbage-first heap   total 16384K, used 761K [0x05000000, 0x06000000, 0x15000000)

when should it send the GC notification? 

With CMS the old understanding I have was that CMS does the background collection and so when System.gc returns, the collection is not prompt and thus the test should use -XX:+ExplicitGCInvokesConcurrent to get CMS to run in foreground.  Does this still apply in CMS?  G1?


------------------------------------------------

 $ java -XX:+PrintGCDetails -Xmx2m -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent CollectionUsageThreshold

Collection usage threshold of G1 Old Gen set to 10
Calling System.gc()
[GC pause (System.gc()) (young) (initial-mark), 0.0014598 secs]
   [Parallel Time: 1.1 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 108.0, Avg: 108.0, Max: 108.0, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.4, Max: 1.1, Diff: 1.0, Sum: 1.6]
      [Code Root Marking (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.5, Max: 0.8, Diff: 0.8, Sum: 2.1]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 0.7]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 1.1, Avg: 1.1, Max: 1.1, Diff: 0.0, Sum: 4.4]
      [GC Worker End (ms): Min: 109.1, Avg: 109.1, Max: 109.1, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Migration: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 1024.0K(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->1024.0K Heap: 1013.0K(2048.0K)->771.1K(20
48.0K)]
 [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0006285 secs]
[GC concurrent-mark-start]
[GC concurrent-mark-end, 0.0001223 secs]
[GC remark [GC ref-proc, 0.0000957 secs], 0.0005657 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC cleanup 791K->791K(2048K), 0.0002172 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

-----------------
Similar issue might happen  -XX:+UseConcMarkSweepGC -XX:+ExplicitGCInvokesConcurrent.

Comments
Sorry, I thought I was editing newly created task - don't know why this one has been selected. I hope I did reset the attributes back to previous values (except subcomponent, which was "gc" but I don't have permission to change it now).
22-08-2016

Jon clarified that System.gc triggers a stop-the-world collection in all collectors. So -XX:+ExplicitGCInvokesConcurrent will do a concurrent GC and thus it explains the test failure.
05-12-2013