Number of CMS collections and the JMM GC counters

Kevin Walls kevin.walls at oracle.com
Thu Jul 28 14:12:45 UTC 2011


Hi --

6580448 was marked as a duplicate of 6581734, which fixed the fact that 
CMS collections were just not counted at all - with CMS, only a stop the 
world full gc would be counted in the stats.

But looks like you're right...  Here is a quick variation of the 
testcase from 6581734 which shows the same thing, and this verifies the 
same, and is solved by ExplicitGCInvokesConcurrent.  If there is no 
other feedback I can test if the removal of the 
TraceCMSMemoryManagerStats() call in CMSCollector::do_compaction_work is 
all we need...

Regards
Kevin


/*
  * Copyright (c) 2011, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
  * under the terms of the GNU General Public License version 2 only, as
  * published by the Free Software Foundation.
  *
  * This code is distributed in the hope that it will be useful, but WITHOUT
  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  * version 2 for more details (a copy is included in the LICENSE file that
  * accompanied this code).
  *
  * You should have received a copy of the GNU General Public License 
version
  * 2 along with this work; if not, write to the Free Software Foundation,
  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
  *
  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
  * or visit www.oracle.com if you need additional information or have any
  * questions.
  */

/*
  * @test TestFullGCount.java
  * @bug
  * @summary
  * @run main/othervm -XX:+UseConcMarkSweepGC TestFullGCCount
  *
  */
import java.util.*;
import java.lang.management.*;



public class TestFullGCCount {

private String poolName = "CMS";
private String collectorName = "ConcurrentMarkSweep";

public static void main(String [] args) {

     TestFullGCCount t = null;
     if (args.length==2) {
         t = new TestFullGCCount(args[0], args[1]);
     } else {
         System.out.println("Defaulting to monitor CMS pool and 
collector.");
         t = new TestFullGCCount();
     }
     t.run();

}

public TestFullGCCount(String pool, String collector) {
     poolName = pool;
     collectorName = collector;
}
public TestFullGCCount() {
}

public void run() {

     int count = 0;
     int iterations = 20;
     long counts[] = new long[iterations];
     boolean diffAlways2 = true; // assume we will fail

     for (int i=0; i<iterations; i++) {
         System.gc();
         counts[i] = checkStats();
         if (i>0) {
             if (counts[i] - counts[i-1] != 2) {
                 diffAlways2 = false;
             }
         }
     }
     if (diffAlways2) {
         throw new RuntimeException("FAILED: difference in count is 
always 2.");
     }
     System.out.println("Passed.");
}

private long checkStats() {
     long count = 0;
     List<MemoryPoolMXBean> pools = 
ManagementFactory.getMemoryPoolMXBeans();
     List<GarbageCollectorMXBean> collectors = 
ManagementFactory.getGarbageCollectorMXBeans();
     for (int i=0; i<collectors.size(); i++) {
         GarbageCollectorMXBean collector = collectors.get(i);
         String name = collector.getName();
         if (name.contains(collectorName)) {
             System.out.println(name + ": collection count = "
                                + collector.getCollectionCount());
             count = collector.getCollectionCount();
         }
     }
     return count;
}

}


On 27/07/11 17:12, Krystal Mok wrote:
> Hi all,
>
> I've been looking at a strange inconsistency of full GC count recorded 
> by jvmstat and JMM counters. I'd like to know which ones of the 
> following behaviors are by design, which ones are bugs, and which ones 
> are just my misunderstanding. I apologize for making a short story long...
>
> =====================================================
>
> The counters involved:
>
> * A jvmstat counter named "sun.gc.collector.1.invocations" keeps track 
> of the number of pauses occured as a result of a major collection. It 
> is used by utilities such as jstat as the source of "FGC" (full 
> collection count), and the old gen collection count in Visual GC. It's 
> updated by an TraceCollectorStats object.
> * A JMM counter, GCMemoryManager::_num_collections, keeps track of the 
> number of collections that have ended. This counter is used as 
> HotSpot's implementation of the JMX 
> GarbageCollectorMXBean.getCollectionCount(). It's updated by either a 
> TraceMemoryManagerStats object or a TraceCMSMemoryManagerStats object.
>
> To show the situation, I've made a screenshot of a VisualVM and a 
> JConsole running side by side, both are monitoring the VisualVM's GC 
> stats:
> http://dl.iteye.com/upload/attachment/524811/913cb0e1-7add-3ac0-a718-24ca705cad22.png
> (I'll upload the screenshot to somewhere else if anybody can't see it)
> The VisualVM instance is running on JDK6u26, with ParNew+CMS.
> In the screenshot, Visual GC reports that the old gen collection count 
> is 20, while JConsole reports 10.
>
> I see that there was this bug:
> 6580448: CMS: Full GC collection count mismatch between 
> GarbageCollectorMXBean and jvmstat (VisualGC)
> I don't think the current implementation has a bug in the sense that 
> the two counters don't report the same number.
>
> This behavior seems reasonable, but the naming of the value in these 
> tools are confusing: both tools say "collections", but apparently the 
> number in Visual GC means "number of pauses" where as the number in 
> JConsole means "number of collection cycles". It'd be great if the 
> difference could be documented somewhere, if that's the intended behavior.
>
> And then the buggy behavior. Code demo posted on gist: 
> https://gist.github.com/1106263
> Starting from JDK6u23, when using CMS without 
> ExplicitGCInvokesConcurrent, System.gc() (or 
> Runtime.getRuntime().gc(), or MemoryMXBean.gc() via JMX) would make 
> the JMM GC counter increment by 2 per invocation, while the jvmstat 
> counter is only incremented by 1. I believe the latter is correct and 
> the former needs some fixing.
>
> =====================================================
>
> My understanding of the behavior shown above:
>
> 1. The concurrent GC part:
>
> There are 2 pauses in a CMS concurrent GC cycle, one in the initial 
> mark phase, and one in the final remark phase.
> To trigger a concurrent GC cycle, the CMS thread wakes up periodically 
> to see if it shouldConcurrentCollect(), and trigger a cycle when the 
> predicate returned true, or goes back to sleep if the predicate 
> returned false. The whole concurrent GC cycle doesn't go through 
> GenCollectedHeap::do_collection().
>
> The jvmstat counter for old gen pauses is updated in 
> CMSCollector::do_CMS_operation(CMS_op_type op), which exactly covers 
> both pause phases.
>
> The JMM counter, however, is updated in the concurrent sweep phase, 
> CMSCollector::sweep(bool asynch), if there was no concurrent mode 
> failure; or it is updated in CMSCollector::do_compaction_work(bool 
> clear_all_soft_refs) in case of a bailout due to concurrent mode 
> failure (advertised as so in the code comments). So that's an 
> increment by 1 per concurrent GC cycle, which does reflect the "number 
> of collection cycles", fair enough.
>
> So far so good.
>
> 2. The System.gc() part:
>
> Without ExplicitGCInvokesConcurrent set, System.gc() does a 
> stop-the-world full GC, which consists of only one pause, so "number 
> of pauses" would equal "number of collections" in this case.
> It will go into GenCollectedHeap::do_collection(); both the jvmstat 
> and the JMM GC counter gets incremented by 1 here,
>
> TraceCollectorStats tcs(_gens[i]->counters());
> TraceMemoryManagerStats tmms(_gens[i]->kind());
>
> But, drilling down into:
> _gens[i]->collect(full, do_clear_all_soft_refs, size, is_tlab);
>
> That'll eventually go into:
> CMSCollector::acquire_control_and_collect(bool full, bool 
> clear_all_soft_refs)
>
> System.gc() is user requested so that'll go further into 
> mark-sweep-compact:
> CMSCollector::do_compaction_work(bool clear_all_soft_refs)
> And here, it increments the JMM GC counter again (remember it was in 
> the concurrent GC path too, to handle bailouts), even though this is 
> still in the same collection. This leads to the "buggy behavior" 
> mentioned earlier.
>
> The JMM GC counter wasn't added to CMS until this fix got in:
> 6581734: CMS Old Gen's collection usage is zero after GC which is 
> incorrect
>
> The code added to CMSCollector::do_compaction_work() works fine in the 
> concurrent GC path, but interacts badly with the original logic in 
> GenCollectedHeap::do_collection().
>
> =====================================================
>
> I thought all concurrent mode failures/interrupts come from 
> GenCollectedHeap::do_collection(). If that's the case, then it seems 
> unnecessary to update the JMM GC counter in 
> CMSCollector::do_compaction_work(), simply removing it should fix the 
> problem.
>
> With that, I'd purpose the following (XS) change: (diff against HS20)
>
> diff -r f0f676c5a2c6 
> src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp
> --- 
> a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp 
>      Tue Mar 15 19:30:16 2011 -0700
> +++ 
> b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp 
>      Thu Jul 28 00:02:41 2011 +0800
> @@ -2022,9 +2022,6 @@
>                                             
>  _intra_sweep_estimate.padded_average());
>    }
>
> -  {
> -    TraceCMSMemoryManagerStats();
> -  }
>    GenMarkSweep::invoke_at_safepoint(_cmsGen->level(),
>      ref_processor(), clear_all_soft_refs);
>    #ifdef ASSERT
>
> The same goes for the changes in:
> 7036199: Adding a notification to the implementation of 
> GarbageCollectorMXBeans
>
> =====================================================
>
> P.S. Is there an "official" name for the counters that I referred to 
> as "jvmstat counters" above? Is it just jvmstat, or PerfData or 
> HSPERFDATA?

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20110728/9ac44865/attachment.htm>


More information about the hotspot-gc-dev mailing list