JDK-8170067 : -XX:ExplicitGCInvokesConcurrentAndUnloadsClasses is not implemented for G1
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 8,9
  • Priority: P3
  • Status: Closed
  • Resolution: Won't Fix
  • OS: linux
  • CPU: x86
  • Submitted: 2016-11-10
  • Updated: 2017-05-19
  • Resolved: 2016-11-30
Related Reports
Relates :  
Description
FULL PRODUCT VERSION :
 "1.8.0_102" 
"1.8.0_91"
At the least.  No evidence of changes in later versions.

FULL OS VERSION :
Multiple Linux distributions, also Mac OS X, potentially windows and Solaris too

EXTRA RELEVANT SYSTEM CONFIGURATION :
Confirmed across multiple Java versions and system configurations

A DESCRIPTION OF THE PROBLEM :
Invoking a program using the G1 garbage collector with the flag -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses  silently does nothing with, rather than behaving as -XX:+ExplicitGCInvokesConcurrent or throwing an error. 

For people migrating from CMS garbage collector to G1, this is a serious problem, because they are likely to retain the non CMS-specific settings.  In CMS land, ExplicitGCInvokesConcurrentAndUnloadsClasses is a safe option used to help ensure that class cleanup is performed when needed (example, with RMI) without the gigantic stop the world pauses from Full GC. 

If you use this option by mistake with G1, as I have now seen on several larger systems in including in production settings... then you silently get long stop-the-world pauses (10s of seconds, even!).

THE PROBLEM WAS REPRODUCIBLE WITH -Xint FLAG: Did not try

THE PROBLEM WAS REPRODUCIBLE WITH -server FLAG: Yes

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
1.  Run an application that includes or allows you to execute explicit System.gc() calls, using these settings:

-Xloggc:gc-%t.log -XX:+PrintGCDetails -XX:+PrintGCCause -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses

2. Trigger System.gc() in the application
3. Look at GC logs for FullGC
4.  Run the same but use -XX:+ExplicitGCInvokesConcurrent instead of  -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses
5. Look at GC logs - concurrent GC is invoked. 



EXPECTED VERSUS ACTUAL BEHAVIOR :
Expected: 

ExplicitGCInvokesConcurrentAndUnloadsClasses reverts to just ExplicitGCInvokesConcurrent behavior (possibly printing a warning statement).  Calls to System.gc() invoke the G1 concurrently, not the serial full GC. 

GC logs should show something like his: 

331.327: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: requested by GC cause, GC cause: System.gc()]
6635 {Heap before GC invocations=72 (full 0):

ACTUAL: 

Full GC is invoked.  No warning is printed, no error generated.  

GC Logs show lines like this: 

2016-11-09T20:25:03.835+0000: 117.855: [Full GC (System.gc())
ERROR MESSAGES/STACK TRACES THAT OCCUR :
See expected and actual for the GC log messages

REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
public class Main {
    public static void main(String[] args) {
        try {
            Thread.sleep(100);    
        } catch (InterruptedException ie) {
            
        }
        System.gc();
    }
}
---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
No workaround possible.  The argument doesn't work -- you have to know this, and not use it.


Comments
The flag has been deprecated for JDK 9, see https://bugs.openjdk.java.net/browse/JDK-8170388
30-11-2016

Just to be clear, -XX:ExplicitGCInvokesConcurrent will result in the same behavior for G1, since G1 already unloads classes after a concurrent mark (on by default). So an easy workaround is to use -XX:+ExplicitGCInvokesConcurrent instead of -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses.
23-11-2016

It is regression, In CMS land, ExplicitGCInvokesConcurrentAndUnloadsClasses is a safe option used to help ensure that class cleanup is performed when needed without stop the world pauses from Full GC
21-11-2016

Below is the output executed on 9 ea b-144 == -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses== -sh-4.1$ /opt/java/jdk-9_ea-144/bin/java -Xlog:gc:gc-%t.log -XX:+PrintGCDetails -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses Main [0.004s][warning][gc] -XX:+PrintGCDetails is deprecated. Will use -Xlog:gc* instead. [0.014s][info ][gc,heap] Heap region size: 1M [0.024s][info ][gc ] Using G1 [0.024s][info ][gc,heap,coops] Heap address: 0x00000006d2400000, size: 3804 MB, Compressed Oops mode: Zero based, Oop shift amount: 3 [0.258s][info ][gc,start ] GC(0) Pause Full (System.gc()) [0.259s][info ][gc,phases,start] GC(0) Phase 1: Mark live objects [0.261s][info ][gc,stringtable ] GC(0) Cleaned string and symbol table, strings: 3013 processed, 16 removed, symbols: 17216 processed, 1 removed [0.261s][info ][gc,phases ] GC(0) Phase 1: Mark live objects 2.317ms [0.261s][info ][gc,phases,start] GC(0) Phase 2: Compute new object addresses [0.262s][info ][gc,phases ] GC(0) Phase 2: Compute new object addresses 0.739ms [0.262s][info ][gc,phases,start] GC(0) Phase 3: Adjust pointers [0.263s][info ][gc,phases ] GC(0) Phase 3: Adjust pointers 1.311ms [0.263s][info ][gc,phases,start] GC(0) Phase 4: Move objects [0.264s][info ][gc,phases ] GC(0) Phase 4: Move objects 1.467ms [0.268s][info ][gc,task ] GC(0) Using 4 workers of 4 to rebuild remembered set [0.269s][info ][gc,heap ] GC(0) Eden regions: 2->0(3) [0.269s][info ][gc,heap ] GC(0) Survivor regions: 0->0(0) [0.269s][info ][gc,heap ] GC(0) Old regions: 0->1 [0.269s][info ][gc,heap ] GC(0) Humongous regions: 0->0 [0.269s][info ][gc,metaspace ] GC(0) Metaspace: 3583K->3583K(1056768K) [0.269s][info ][gc ] GC(0) Pause Full (System.gc()) 2M->0M(8M) 10.808ms [0.269s][info ][gc,cpu ] GC(0) User=0.00s Sys=0.00s Real=0.01s [0.270s][info ][gc,heap,exit ] Heap [0.270s][info ][gc,heap,exit ] garbage-first heap total 8192K, used 894K [0x00000006d2400000, 0x00000006d2500040, 0x00000007c0000000) [0.270s][info ][gc,heap,exit ] region size 1024K, 1 young (1024K), 0 survivors (0K) [0.270s][info ][gc,heap,exit ] Metaspace used 3590K, capacity 4492K, committed 4864K, reserved 1056768K [0.270s][info ][gc,heap,exit ] class space used 345K, capacity 388K, committed 512K, reserved 1048576K ==-XX:+ExplicitGCInvokesConcurrent== -sh-4.1$ /opt/java/jdk-9_ea-144/bin/java -Xlog:gc:gc-%t.log -XX:+PrintGCDetails -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent Main [0.004s][warning][gc] -XX:+PrintGCDetails is deprecated. Will use -Xlog:gc* instead. [0.013s][info ][gc,heap] Heap region size: 1M [0.022s][info ][gc ] Using G1 [0.022s][info ][gc,heap,coops] Heap address: 0x00000006d2400000, size: 3804 MB, Compressed Oops mode: Zero based, Oop shift amount: 3 [0.245s][info ][gc,start ] GC(0) Pause Initial Mark (System.gc()) [0.245s][info ][gc,task ] GC(0) Using 4 workers of 4 for evacuation [0.248s][info ][gc,phases ] GC(0) Evacuate Collection Set: 2.4ms [0.248s][info ][gc,phases ] GC(0) Code Roots: 0.0ms [0.248s][info ][gc,phases ] GC(0) Clear Card Table: 0.0ms [0.248s][info ][gc,phases ] GC(0) Expand Heap After Collection: 0.0ms [0.248s][info ][gc,phases ] GC(0) Free Collection Set: 0.1ms [0.248s][info ][gc,phases ] GC(0) Merge Per-Thread State: 0.0ms [0.248s][info ][gc,phases ] GC(0) Other: 0.4ms [0.248s][info ][gc,heap ] GC(0) Eden regions: 2->0(141) [0.248s][info ][gc,heap ] GC(0) Survivor regions: 0->1(2) [0.248s][info ][gc,heap ] GC(0) Old regions: 0->0 [0.248s][info ][gc,heap ] GC(0) Humongous regions: 0->0 [0.248s][info ][gc,metaspace ] GC(0) Metaspace: 3582K->3582K(1056768K) [0.248s][info ][gc ] GC(0) Pause Initial Mark (System.gc()) 2M->0M(238M) 3.079ms [0.248s][info ][gc,cpu ] GC(0) User=0.00s Sys=0.00s Real=0.00s [0.248s][info ][gc ] GC(1) Concurrent Cycle [0.248s][info ][gc,marking ] GC(1) Concurrent Clear Claimed Marks [0.248s][info ][gc,marking ] GC(1) Concurrent Clear Claimed Marks 0.018ms [0.248s][info ][gc,marking ] GC(1) Concurrent Scan Root Regions [0.249s][info ][gc,marking ] GC(1) Concurrent Scan Root Regions 0.659ms [0.249s][info ][gc,marking ] GC(1) Concurrent Mark (0.249s) [0.249s][info ][gc,marking ] GC(1) Concurrent Mark From Roots [0.249s][info ][gc,task ] GC(1) Using 1 workers of 1 for marking [0.249s][info ][gc,marking ] GC(1) Concurrent Mark From Roots 0.649ms [0.249s][info ][gc,marking ] GC(1) Concurrent Mark (0.249s, 0.249s) 0.683ms [0.250s][info ][gc,start ] GC(1) Pause Remark [0.251s][info ][gc,stringtable] GC(1) Cleaned string and symbol table, strings: 3013 processed, 0 removed, symbols: 17216 processed, 1 removed [0.251s][info ][gc ] GC(1) Pause Remark 0M->0M(238M) 1.532ms [0.251s][info ][gc,cpu ] GC(1) User=0.01s Sys=0.00s Real=0.00s [0.251s][info ][gc,marking ] GC(1) Concurrent Create Live Data [0.251s][info ][gc,marking ] GC(1) Concurrent Create Live Data 0.073ms [0.251s][info ][gc,start ] GC(1) Pause Cleanup [0.252s][info ][gc ] GC(1) Pause Cleanup 0M->0M(238M) 0.423ms [0.252s][info ][gc,cpu ] GC(1) User=0.00s Sys=0.00s Real=0.00s [0.252s][info ][gc,marking ] GC(1) Concurrent Cleanup for Next Mark [0.256s][info ][gc,marking ] GC(1) Concurrent Cleanup for Next Mark 4.492ms [0.256s][info ][gc ] GC(1) Concurrent Cycle 8.486ms [0.257s][info ][gc,heap,exit ] Heap [0.257s][info ][gc,heap,exit ] garbage-first heap total 243712K, used 923K [0x00000006d2400000, 0x00000006d2500770, 0x00000007c0000000) [0.257s][info ][gc,heap,exit ] region size 1024K, 2 young (2048K), 1 survivors (1024K) [0.257s][info ][gc,heap,exit ] Metaspace used 3590K, capacity 4492K, committed 4864K, reserved 1056768K [0.257s][info ][gc,heap,exit ] class space used 345K, capacity 388K, committed 512K, reserved 1048576K
21-11-2016

GC logs when executed using "-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses" == -sh-4.1$ /opt/java/jdk1.8.0_112/bin/java -Xloggc:gc-%t.log -XX:+PrintGCDetails -XX:+PrintGCCause -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses Main Java HotSpot(TM) 64-Bit Server VM (25.112-b15) for linux-amd64 JRE (1.8.0_112-b15), built on Sep 22 2016 21:10:53 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8) Memory: 4k page, physical 15576904k(5717540k free), swap 15949804k(15949804k free) CommandLine flags: -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses -XX:InitialHeapSize=249230464 -XX:MaxHeapSize=3987687424 -XX:+PrintGC -XX:+PrintGCCause -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC 0.225: [Full GC (System.gc()) 860K->258K(8192K), 0.0123065 secs] [Eden: 1024.0K(14.0M)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 860.3K(238.0M)->258.3K(8192.0K)], [Metaspace: 2479K->2479K(1056768K)] [Times: user=0.01 sys=0.00, real=0.01 secs] Heap garbage-first heap total 8192K, used 258K [0x00000006d2400000, 0x00000006d2500040, 0x00000007c0000000) region size 1024K, 1 young (1024K), 0 survivors (0K) Metaspace used 2486K, capacity 4486K, committed 4864K, reserved 1056768K class space used 269K, capacity 386K, committed 512K, reserved 1048576K == GC logs when executed using "--XX:+ExplicitGCInvokesConcurrent" == -sh-4.1$ /opt/java/jdk1.8.0_112/bin/java -Xloggc:gc-%t.log -XX:+PrintGCDetails -XX:+PrintGCCause -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent Main Java HotSpot(TM) 64-Bit Server VM (25.112-b15) for linux-amd64 JRE (1.8.0_112-b15), built on Sep 22 2016 21:10:53 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8) Memory: 4k page, physical 15576904k(5717884k free), swap 15949804k(15949804k free) CommandLine flags: -XX:+ExplicitGCInvokesConcurrent -XX:InitialHeapSize=249230464 -XX:MaxHeapSize=3987687424 -XX:+PrintGC -XX:+PrintGCCause -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC 0.269: [GC pause (System.gc()) (young) (initial-mark), 0.0021382 secs] [Parallel Time: 1.2 ms, GC Workers: 4] [GC Worker Start (ms): Min: 269.0, Avg: 269.1, Max: 269.2, Diff: 0.1] [Ext Root Scanning (ms): Min: 0.4, Avg: 0.5, Max: 0.6, Diff: 0.1, Sum: 2.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.3, Avg: 0.4, Max: 0.4, Diff: 0.0, Sum: 1.4] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Termination Attempts: Min: 1, Avg: 2.2, Max: 4, Diff: 3, Sum: 9] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.2] [GC Worker Total (ms): Min: 0.9, Avg: 0.9, Max: 1.0, Diff: 0.1, Sum: 3.7] [GC Worker End (ms): Min: 270.0, Avg: 270.0, Max: 270.0, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.2 ms] [Other: 0.8 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.3 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.2 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 1024.0K(14.0M)->0.0B(14.0M) Survivors: 0.0B->1024.0K Heap: 573.6K(238.0M)->368.1K(238.0M)] [Times: user=0.01 sys=0.00, real=0.00 secs] 0.271: [GC concurrent-root-region-scan-start] 0.271: [GC concurrent-root-region-scan-end, 0.0003261 secs] 0.271: [GC concurrent-mark-start] 0.272: [GC concurrent-mark-end, 0.0008492 secs] 0.272: [GC remark 0.273: [Finalize Marking, 0.0002313 secs] 0.273: [GC ref-proc, 0.0003688 secs] 0.273: [Unloading, 0.0011036 secs], 0.0020180 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 0.275: [GC cleanup 368K->368K(238M), 0.0008936 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] Heap garbage-first heap total 243712K, used 368K [0x00000006d2400000, 0x00000006d2500770, 0x00000007c0000000) region size 1024K, 2 young (2048K), 1 survivors (1024K) Metaspace used 2484K, capacity 4486K, committed 4864K, reserved 1056768K class space used 269K, capacity 386K, committed 512K, reserved 1048576K
21-11-2016