JDK-6369463 : different num. of GCs between verbose:gc and mxbeans in 6.0b65
  • Type: Bug
  • Component: core-svc
  • Sub-Component: java.lang.management
  • Affected Version: 5.0,6
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • OS: generic,windows_xp
  • CPU: generic,x86
  • Submitted: 2006-01-06
  • Updated: 2010-08-05
  • Resolved: 2006-04-26
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 6
6 b82Fixed
Related Reports
Duplicate :  
JDK-5073422 - reported GC statistics do not match jstat or verbosegc statistics
Relates :  
JDK-6941050 - Adjust GC time both of GC MXBean and verbose: gc in CMS
Description
When a user measure the num. of GCs, the result in verbose:gc and mxbeans seems different.

REPRODUCING and BEHAVIOR:
The attached test progtam, GCBeanTEST.java tries to allocate 4M memory 100 times.

1) Compile the test program and invoke the following command line.
   java -Xms64m -XX:+UseSerialGC -XX:NewRatio=12 -verbose:gc GCBeanTEST
   NOTE:
      -XX:+UseSerialGC and -XX:NewRatio=12 is added to avoid that runtime system 
      considers the PC as "server" machine.(to avoid auto-configuration)

The following message will appear

K:\shares2\gc>java -Xms64m -XX:+UseSerialGC -XX:NewRato=12 -verbose:gc GCBeanTEST
[GC 285K->133K(65088K), 0.0046967 secs]
[Full GC 133K->133K(65088K), 0.0156947 secs]
[GC 4229K->4229K(65088K), 0.0006263 secs]
[Full GC 4229K->133K(65088K), 0.0160146 secs]
[GC 4229K->4229K(65088K), 0.0004048 secs]
[Full GC 4229K->133K(65088K), 0.0281636 secs]
[GC 4229K->4229K(65088K), 0.0003623 secs]
[Full GC 4229K->133K(65088K), 0.0186784 secs]
[GC 4229K->4229K(65088K), 0.0003084 secs]
[Full GC 4229K->133K(65088K), 0.0153316 secs]
..........
sun.management.GarbageCollectorImpl@82c01f, sun.management.GarbageCollectorImp
@133796]

----- Copy -----
sun.management.GarbageCollectorImpl@82c01f
GarbageCollectorMXBean.getName():Copy
GarbageCollectorMXBean.getCollectionCount():100
GarbageCollectorMXBean.getCollectionTime():1962
------------------------------------

----- MarkSweepCompact -----
sun.management.GarbageCollectorImpl@133796
GarbageCollectorMXBean.getName():MarkSweepCompact
GarbageCollectorMXBean.getCollectionCount():0
GarbageCollectorMXBean.getCollectionTime():0
------------------------------------

INVESTIGATION:
  The messages by -verbose:gc 
...
 [GC 4229K->4229K(65088K), 0.0003084 secs]
 [Full GC 4229K->133K(65088K), 0.0153316 secs]
....
  says GC anf Full GC occurs 100 times respectively.
  However, messages by mxbeans shows that CopyGC occurs 100 times

   GarbageCollectorMXBean.getCollectionCount():100

  and FullGC(MarkSweepCompact) occurs "0" times.(FullGC does not occur.)

   GarbageCollectorMXBean.getCollectionCount():0

----- Copy -----
sun.management.GarbageCollectorImpl@82c01f
GarbageCollectorMXBean.getName():Copy
GarbageCollectorMXBean.getCollectionCount():100
GarbageCollectorMXBean.getCollectionTime():1962
------------------------------------

----- MarkSweepCompact -----
sun.management.GarbageCollectorImpl@133796
GarbageCollectorMXBean.getName():MarkSweepCompact
GarbageCollectorMXBean.getCollectionCount():0
GarbageCollectorMXBean.getCollectionTime():0
------------------------------------

EXPECTED BEHAVIOR:
  FullGC seems to occur 100 times, but mxbeans says FullGC does not occur.
  hHose results shgould be the same.
Comments
EVALUATION So fix is move the memory manager trace collector helper object inside a loop where it runs both collector. And collector type is determined by the generation kind.
04-04-2006
EVALUATION MM code makes the basic assumption of full gc or partial gc to find the collector and I think that assumption is not correct. For example when full GC is requested with CollectGen0First option it runs the gc collection on DefNewGeneration which runs copy collector also in addition running gc on tennured generation which uses copy collector. And when partial gc is requested it runs copy collector on def new generation and then runs mark and sweep collector on tenured generation. So basic assumption of full or partial gc to find the collector seems to be not correct. Investigating the possible solution for this problem. -Swamy
21-02-2006
EVALUATION The bug can be reproduced when using Serial GC and Concurrent MarkSweep GC with 5.0 and 6.0. Parallel GC works.
06-01-2006