<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
  <head>
    <meta content="text/html; charset=ISO-8859-1"
      http-equiv="Content-Type">
  </head>
  <body bgcolor="#ffffff" text="#000000">
    Hi --<br>
    <br>
    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.<br>
    <br>
    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...<br>
    <br>
    Regards<br>
    Kevin<br>
    <br>
    <br>
    /*<br>
     * Copyright (c) 2011, Oracle and/or its affiliates. All rights
    reserved.<br>
     * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.<br>
     *<br>
     * This code is free software; you can redistribute it and/or modify
    it<br>
     * under the terms of the GNU General Public License version 2 only,
    as<br>
     * published by the Free Software Foundation.<br>
     *<br>
     * This code is distributed in the hope that it will be useful, but
    WITHOUT<br>
     * ANY WARRANTY; without even the implied warranty of
    MERCHANTABILITY or<br>
     * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public
    License<br>
     * version 2 for more details (a copy is included in the LICENSE
    file that<br>
     * accompanied this code).<br>
     *<br>
     * You should have received a copy of the GNU General Public License
    version<br>
     * 2 along with this work; if not, write to the Free Software
    Foundation,<br>
     * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.<br>
     *<br>
     * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA
    94065 USA<br>
     * or visit <a class="moz-txt-link-abbreviated" href="http://www.oracle.com">www.oracle.com</a> if you need additional information or
    have any<br>
     * questions.<br>
     */<br>
    <br>
    /*<br>
     * @test TestFullGCount.java<br>
     * @bug <br>
     * @summary<br>
     * @run main/othervm -XX:+UseConcMarkSweepGC TestFullGCCount<br>
     *<br>
     */<br>
    import java.util.*;<br>
    import java.lang.management.*;<br>
    <br>
    <br>
    <br>
    public class TestFullGCCount {<br>
    <br>
    private String poolName = "CMS";<br>
    private String collectorName = "ConcurrentMarkSweep";<br>
    <br>
    public static void main(String [] args) {<br>
    <br>
        TestFullGCCount t = null;<br>
        if (args.length==2) {<br>
            t = new TestFullGCCount(args[0], args[1]);<br>
        } else {<br>
            System.out.println("Defaulting to monitor CMS pool and
    collector.");<br>
            t = new TestFullGCCount();<br>
        }<br>
        t.run();<br>
    <br>
    }<br>
    <br>
    public TestFullGCCount(String pool, String collector) {<br>
        poolName = pool;<br>
        collectorName = collector;<br>
    }<br>
    public TestFullGCCount() {<br>
    }<br>
    <br>
    public void run() {<br>
    <br>
        int count = 0;<br>
        int iterations = 20;<br>
        long counts[] = new long[iterations];<br>
        boolean diffAlways2 = true; // assume we will fail<br>
    <br>
        for (int i=0; i<iterations; i++) {<br>
            System.gc();<br>
            counts[i] = checkStats();<br>
            if (i>0) {<br>
                if (counts[i] - counts[i-1] != 2) {<br>
                    diffAlways2 = false;<br>
                }<br>
            }<br>
        }<br>
        if (diffAlways2) {<br>
            throw new RuntimeException("FAILED: difference in count is
    always 2.");<br>
        }<br>
        System.out.println("Passed."); <br>
    }<br>
    <br>
    private long checkStats() {<br>
        long count = 0;<br>
        List<MemoryPoolMXBean> pools =
    ManagementFactory.getMemoryPoolMXBeans();<br>
        List<GarbageCollectorMXBean> collectors =
    ManagementFactory.getGarbageCollectorMXBeans();<br>
        for (int i=0; i<collectors.size(); i++) {<br>
            GarbageCollectorMXBean collector = collectors.get(i);<br>
            String name = collector.getName();<br>
            if (name.contains(collectorName)) {<br>
                System.out.println(name + ": collection count = " <br>
                                   + collector.getCollectionCount());<br>
                count = collector.getCollectionCount();<br>
            }<br>
        }<br>
        return count;<br>
    }<br>
    <br>
    }<br>
    <br>
    <br>
    On 27/07/11 17:12, Krystal Mok wrote:
    <blockquote
cite="mid:CA+cQ+tQJPD+drB12x7ZQHQi_=D2G-SxJ8YKULDfCKKOvSM4orQ@mail.gmail.com"
      type="cite">
      <div>Hi all,</div>
      <div><br>
      </div>
      <div>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...</div>
      <div><br>
      </div>
      <div>=====================================================</div>
      <div><br>
      </div>
      <div>The counters involved:</div>
      <div><br>
      </div>
      <div>* 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.</div>
      <div>* 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.</div>
      <div><br>
      </div>
      <div>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:</div>
      <div><a moz-do-not-send="true"
href="http://dl.iteye.com/upload/attachment/524811/913cb0e1-7add-3ac0-a718-24ca705cad22.png">http://dl.iteye.com/upload/attachment/524811/913cb0e1-7add-3ac0-a718-24ca705cad22.png</a></div>
      <div>(I'll upload the screenshot to somewhere else if anybody
        can't see it)</div>
      <div>The VisualVM instance is running on JDK6u26, with ParNew+CMS.</div>
      <div>In the screenshot, Visual GC reports that the old gen
        collection count is 20, while JConsole reports 10.</div>
      <div><br>
      </div>
      <div>I see that there was this bug:</div>
      <div>6580448: CMS: Full GC collection count mismatch between
        GarbageCollectorMXBean and jvmstat (VisualGC)</div>
      <div>I don't think the current implementation has a bug in the
        sense that the two counters don't report the same number.</div>
      <div><br>
      </div>
      <div>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.</div>
      <div><br>
      </div>
      <div>And then the buggy behavior. Code demo posted on gist: <a
          moz-do-not-send="true" href="https://gist.github.com/1106263">https://gist.github.com/1106263</a></div>
      <div>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.</div>
      <div><br>
      </div>
      <div>=====================================================</div>
      <div><br>
      </div>
      <div>My understanding of the behavior shown above:</div>
      <div><br>
      </div>
      <div>1. The concurrent GC part:</div>
      <div><br>
      </div>
      <div>
        There are 2 pauses in a CMS concurrent GC cycle, one in the
        initial mark phase, and one in the final remark phase.</div>
      <div>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().</div>
      <div><br>
      </div>
      <div>The jvmstat counter for old gen pauses is updated in
        CMSCollector::do_CMS_operation(CMS_op_type op), which exactly
        covers both pause phases.</div>
      <div><br>
      </div>
      <div>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.</div>
      <div><br>
      </div>
      <div>So far so good.</div>
      <div><br>
      </div>
      <div>2. The System.gc() part:</div>
      <div><br>
      </div>
      <div>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.</div>
      <div>It will go into GenCollectedHeap::do_collection(); both the
        jvmstat and the JMM GC counter gets incremented by 1 here,</div>
      <div><br>
      </div>
      <div>TraceCollectorStats tcs(_gens[i]->counters());</div>
      <div>TraceMemoryManagerStats tmms(_gens[i]->kind());</div>
      <div><br>
      </div>
      <div>But, drilling down into:</div>
      <div>_gens[i]->collect(full, do_clear_all_soft_refs, size,
        is_tlab);</div>
      <div><br>
      </div>
      <div>That'll eventually go into:</div>
      <div>CMSCollector::acquire_control_and_collect(bool full, bool
        clear_all_soft_refs)</div>
      <div><br>
      </div>
      <div>System.gc() is user requested so that'll go further into
        mark-sweep-compact:</div>
      <div>CMSCollector::do_compaction_work(bool clear_all_soft_refs)</div>
      <div>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.</div>
      <div><br>
      </div>
      <div>The JMM GC counter wasn't added to CMS until this fix got in:</div>
      <div>6581734: CMS Old Gen's collection usage is zero after GC
        which is incorrect</div>
      <div><br>
      </div>
      <div>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().</div>
      <div><br>
      </div>
      <div>=====================================================</div>
      <div><br>
      </div>
      <div>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.</div>
      <div><br>
      </div>
      <div>With that, I'd purpose the following (XS) change: (diff
        against HS20)</div>
      <div><br>
      </div>
      <div><font class="Apple-style-span" face="'courier new',
          monospace">diff -r f0f676c5a2c6
src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp</font></div>
      <div><font class="Apple-style-span" face="'courier new',
          monospace">---
          a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp
               Tue Mar 15 19:30:16 2011 -0700</font></div>
      <div><font class="Apple-style-span" face="'courier new',
          monospace">+++
          b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp
               Thu Jul 28 00:02:41 2011 +0800</font></div>
      <div><font class="Apple-style-span" face="'courier new',
          monospace">@@ -2022,9 +2022,6 @@</font></div>
      <div><font class="Apple-style-span" face="'courier new',
          monospace">                                           
           _intra_sweep_estimate.padded_average());</font></div>
      <div><font class="Apple-style-span" face="'courier new',
          monospace">   }</font></div>
      <div><font class="Apple-style-span" face="'courier new',
          monospace"><br>
        </font></div>
      <div><font class="Apple-style-span" face="'courier new',
          monospace">-  {</font></div>
      <div><font class="Apple-style-span" face="'courier new',
          monospace">-    TraceCMSMemoryManagerStats();</font></div>
      <div><font class="Apple-style-span" face="'courier new',
          monospace">-  }</font></div>
      <div>
        <font class="Apple-style-span" face="'courier new', monospace"> 
           GenMarkSweep::invoke_at_safepoint(_cmsGen->level(),</font></div>
      <div><font class="Apple-style-span" face="'courier new',
          monospace">     ref_processor(), clear_all_soft_refs);</font></div>
      <div><font class="Apple-style-span" face="'courier new',
          monospace">   #ifdef ASSERT</font></div>
      <div><br>
      </div>
      <div>The same goes for the changes in:</div>
      <div>7036199: Adding a notification to the implementation of
        GarbageCollectorMXBeans</div>
      <div><br>
      </div>
      <div>=====================================================</div>
      <div><br>
      </div>
      <div>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?</div>
    </blockquote>
    <br>
  </body>
</html>