JDK-8073476 : G1 logging ignores changes to PrintGC* flags via MXBeans
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 8,9
  • Priority: P2
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2015-02-19
  • Updated: 2015-06-03
  • Resolved: 2015-04-29
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 9
9 b66Fixed
Related Reports
Blocks :  
Description
VM flags PrintGC, PrintGCDetails and PrintGCTimeStamps are manageable, it means one could alter their initial values calling MXBean.

This works for all collectors, but G1. G1 takes only initial setting into account.
A minimized test demonstrating the problem is attached LogTest


1) java -XX:+UseParallelGC LogTest
----------------------
PrintGC true
----------------------
0.155: [GC (System.gc()) [PSYoungGen: 639K->496K(4096K)] 639K->496K(63488K), 0.0022237 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
0.158: [Full GC (System.gc()) [PSYoungGen: 496K->0K(4096K)] [ParOldGen: 0K->445K(59392K)] 496K->445K(63488K), [Metaspace: 2810K->2810K(1056768K)], 0.0090386 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
....

works fine

2) java -XX:+UseParallelGC LogTest no
----------------------
PrintGC false
----------------------

works fine

3) java -XX:+UseG1GC LogTest no
----------------------
PrintGC false
----------------------

works fine

4) java -XX:+UseG1GC LogTest  
----------------------
PrintGC true
----------------------
Heap
 garbage-first heap   total 8192K, used 446K [0x00000000c0000000, 0x00000000c0800000, 0x0000000100000000)
  region size 1024K, 1 young (1024K), 0 survivors (0K)
 Metaspace       used 2817K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 314K, capacity 386K, committed 512K, reserved 1048576K

works wrong: no Full GC in output!


5) java -XX:+UseG1GC -XX:+PrintGC LogTest
----------------------
PrintGC true
----------------------
0.146: [Full GC (System.gc())  657K->446K(8192K), 0.0131295 secs]
Heap
 garbage-first heap   total 8192K, used 446K [0x00000000c0000000, 0x00000000c0800000, 0x0000000100000000)
  region size 1024K, 1 young (1024K), 0 survivors (0K)
 Metaspace       used 2817K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 314K, capacity 386K, committed 512K, reserved 1048576K

works fine

6) java -XX:+UseG1GC -XX:+PrintGC LogTest off
----------------------
PrintGC false
----------------------
[Full GC (System.gc())  657K->446K(8192K), 0.0123265 secs]

works wrong: Full GC is printed out!












Comments
The root cause in incorrect behavior of class G1Log This class introduces an extra level between GC and Runtime (flags PrintGC*). G1Log::init() is called only once, so further changes to PrintGC* flags have no sense. One possible fix: - update G1Log::fine/finer/finest() methods to deal with PrintGC* flags directly. - remove g1Log.cpp - remove G1Log::init() - remove G1Log::LogLevel enum Looking for alternatives.
20-02-2015

ILW = M (G1 logging is not manageable), High (always), H (none) = P2
20-02-2015