Review request: 7072527 CMS: JMM GC counters overcount in some cases

Kevin Walls kevin.walls at oracle.com
Wed Aug 3 04:56:38 PDT 2011


Thanks Ramki, and thanks for chasing up and clarifying the OCA point.

Kevin



On 01/08/11 19:35, Ramki Ramakrishna wrote:
> Looks good to me; ship it!
>
> -- ramki
>
> On 7/29/2011 4:13 PM, Kevin Walls wrote:
>>
>> Actually I missed the other comment that we could go further and 
>> remove the unneeded constructor.
>>
>> http://cr.openjdk.java.net/~kevinw/7072527/webrev.01/
>>
>> Thanks
>> Kevin
>>
>> On 29/07/11 17:35, Kevin Walls wrote:
>>> Hi --
>>>
>>> I got this ready in a webrev:
>>>
>>> http://cr.openjdk.java.net/~kevinw/7072527/webrev.00/
>>>
>>> The new test is passing, as are the old ones. 8-)
>>>
>>> Also, this change means that a CMS cycle ending in concurrent mode 
>>> failure now counts as one collection.  One could argue that either 
>>> way (should it be 2 collections?) - but I'm thinking if we are 
>>> counting "completed" collections then we are now counting correctly!
>>>
>>> Thanks
>>> Kevin
>>>
>>>
>>> On 29/07/11 02:08, Y. S. Ramakrishna wrote:
>>>> I filed: 7072527 CMS: JMM GC counters overcount in some cases
>>>>
>>>> On 07/28/11 17:29, Y. S. Ramakrishna wrote:
>>>>> Hi Kevin --
>>>>>
>>>>> thanks for jumping on this! More inline below ...
>>>>>
>>>>> On 07/28/11 09:33, Krystal Mok wrote:
>>>>>> Hi Kevin,
>>>>>>
>>>>>> Thank you for taking care of this, and it's good to see the 
>>>>>> problem is verified.
>>>>>>
>>>>>> I think whether or not the suggested fix is sufficient depends on 
>>>>>> what paths can reach CMSCollector::do_compaction_work(). If all 
>>>>>> paths that can reach CMSCollector::do_compaction_work() come from 
>>>>>> GenCollectedHeap::do_collection(), then the fix should be good to 
>>>>>> go. Otherwise it'll need a better workaround.
>>>>>>
>>>>>> I believe all concurrent mode failures/interrupts (which includes 
>>>>>> the System.gc() case) does come from 
>>>>>> GenCollectedHeap::do_collection(), but I'm not exactly sure about 
>>>>>> this, could anybody please clarify on it?
>>>>>
>>>>> Yes, i believe this is indeed the case, and my browsing of the
>>>>> code using cscope seemed to confirm that belief.
>>>>>
>>>>> More below ...
>>>>>
>>>>>>
>>>>>> Regards,
>>>>>> Kris Mok
>>>>>>
>>>>>> On Thu, Jul 28, 2011 at 10:12 PM, Kevin Walls 
>>>>>> <kevin.walls at oracle.com <mailto:kevin.walls at oracle.com>> wrote:
>>>>>>
>>>>>>     __
>>>>>>     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...
>>>>>
>>>>>
>>>>> Kevin, yes, it would be great if you could verify this and push 
>>>>> the fix.
>>>>> I am not sure if the push would need to wait for the signing of OCA
>>>>> from Kris, but best to check with Those Who Would Know Such Things.
>>>>>
>>>>> Since the original CR has been closed, i'll open one momentarily and
>>>>> can make you RE (if that's OK with you). I'll be happy to serve as
>>>>> reviewer of the change.
>>>>>
>>>>> As regards the jstat counter reporting two pauses per concurrent
>>>>> CMS cycle, I am of two minds on what the original intention
>>>>> was. I'd have originally regarded the double increment as a
>>>>> bug, but as you state it is really two pauses, even if part of
>>>>> a single cycle. And it makes sense to count them as two. I
>>>>> agree that this should be documented and left alone, given
>>>>> how long we have had this behaviour, and the alternative
>>>>> (of counting cycles, rather than pauses) may be no better
>>>>> (or arguably worse). There's actually an open CR for this
>>>>> which we can redirect into a CR to update the relevant documentation.
>>>>>
>>>>> -- ramki
>>>>>
>>>>>>
>>>>>>     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 <http://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?
>>>>>>
>>>>>>
>>>
>>



More information about the hotspot-gc-dev mailing list