<div>Hi Ramki,</div><div><br></div><blockquote class="gmail_quote" style="margin-top: 0px; margin-right: 0px; margin-bottom: 0px; margin-left: 0.8ex; border-left-width: 1px; border-left-color: rgb(204, 204, 204); border-left-style: solid; padding-left: 1ex; ">
I agree with your analysis and will review & shepherd your suggested fix.<br>I'll file a CR to cover this fix and send out a CR id shortly.</blockquote><div>Thank you ^_^</div><div><br></div><div>If the suggested fix does fix the problem, then there's more code that can probably go away as well: (diff against HS20)</div>
<div><br></div><blockquote class="gmail_quote" style="margin-top: 0px; margin-right: 0px; margin-bottom: 0px; margin-left: 0.8ex; border-left-width: 1px; border-left-color: rgb(204, 204, 204); border-left-style: solid; padding-left: 1ex; ">
diff -r f0f676c5a2c6 src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp<br>--- a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp<span class="Apple-tab-span" style="white-space:pre"> </span>Tue Mar 15 19:30:16 2011 -0700<br>
+++ b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp<span class="Apple-tab-span" style="white-space:pre"> </span>Thu Jul 28 01:33:33 2011 +0800<br>@@ -2022,9 +2022,6 @@<br> _intra_sweep_estimate.padded_average());<br>
}<br> <br>- {<br>- TraceCMSMemoryManagerStats();<br>- }<br> GenMarkSweep::invoke_at_safepoint(_cmsGen->level(),<br> ref_processor(), clear_all_soft_refs);<br> #ifdef ASSERT<br>@@ -9263,15 +9260,3 @@<br>
ShouldNotReachHere();<br> }<br> }<br>-<br>-// when bailing out of cms in concurrent mode failure<br>-TraceCMSMemoryManagerStats::TraceCMSMemoryManagerStats(): TraceMemoryManagerStats() {<br>- initialize(true /* fullGC */ ,<br>
- true /* recordGCBeginTime */,<br>- true /* recordPreGCUsage */,<br>- true /* recordPeakUsage */,<br>- true /* recordPostGCusage */,<br>- true /* recordAccumulatedGCTime */,<br>
- true /* recordGCEndTime */,<br>- true /* countCollection */ );<br>-}<br>diff -r f0f676c5a2c6 src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp<br>--- a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp<span class="Apple-tab-span" style="white-space:pre"> </span>Tue Mar 15 19:30:16 2011 -0700<br>
+++ b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.hpp<span class="Apple-tab-span" style="white-space:pre"> </span>Thu Jul 28 01:33:33 2011 +0800<br>@@ -1896,7 +1896,6 @@<br> <br> public:<br>
TraceCMSMemoryManagerStats(CMSCollector::CollectorState phase);<br>- TraceCMSMemoryManagerStats();<br> };</blockquote><div><br></div><div><br></div><blockquote class="gmail_quote" style="margin-top: 0px; margin-right: 0px; margin-bottom: 0px; margin-left: 0.8ex; border-left-width: 1px; border-left-color: rgb(204, 204, 204); border-left-style: solid; padding-left: 1ex; ">
If you have not already done so, please complete the contributor <br>agreement (OCA) so that your contribution may be used</blockquote><div>Joseph and I are seeking to get our employer sign the OCA soon. We'll report back when we've got progress.</div>
<div><br></div><div>Thanks,</div><div>Kris Mok</div><br><div class="gmail_quote">On Thu, Jul 28, 2011 at 1:07 AM, Y. Srinivas Ramakrishna <span dir="ltr"><<a href="mailto:y.s.ramakrishna@oracle.com" target="_blank">y.s.ramakrishna@oracle.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hi Kris --<br>
<br>
I agree with your analysis and will review & shepherd your suggested fix.<br>
I'll file a CR to cover this fix and send out a CR id shortly.<br>
<br>
Thanks for the fix. If you have not already done so, please<br>
complete the contributor agreement (OCA) so that your<br>
contribution may be used; see:-<br>
<a href="http://openjdk.java.net/contribute/" target="_blank">http://openjdk.java.net/<u></u>contribute/</a><br>
<br>
-- ramki<div><div></div><div><br>
<br>
On 7/27/2011 9:42 AM, Y. Srinivas Ramakrishna wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Cross-posting to serviceability-dev list. Please include both lists<br>
in your responses to this thread.<br>
<br>
-- ramki<br>
<br>
On 7/27/2011 9:12 AM, Krystal Mok wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Hi all,<br>
<br>
I've been looking at a strange inconsistency of full GC count recorded by<br>
jvmstat and JMM counters. I'd like to know which ones of the following<br>
behaviors are by design, which ones are bugs, and which ones are just my<br>
misunderstanding. I apologize for making a short story long...<br>
<br>
==============================<u></u>=======================<br>
<br>
The counters involved:<br>
<br>
* A jvmstat counter named "sun.gc.collector.1.<u></u>invocations" keeps track of<br>
the number of pauses occured as a result of a major collection. It is used<br>
by utilities such as jstat as the source of "FGC" (full collection count),<br>
and the old gen collection count in Visual GC. It's updated by an<br>
TraceCollectorStats object.<br>
* A JMM counter, GCMemoryManager::_num_<u></u>collections, keeps track of the<br>
number of collections that have ended. This counter is used as HotSpot's<br>
implementation of the JMX GarbageCollectorMXBean.<u></u>getCollectionCount(). It's<br>
updated by either a TraceMemoryManagerStats object or a<br>
TraceCMSMemoryManagerStats object.<br>
<br>
To show the situation, I've made a screenshot of a VisualVM and a JConsole<br>
running side by side, both are monitoring the VisualVM's GC stats:<br>
<a href="http://dl.iteye.com/upload/attachment/524811/913cb0e1-7add-3ac0-a718-24ca705cad22.png" target="_blank">http://dl.iteye.com/upload/<u></u>attachment/524811/913cb0e1-<u></u>7add-3ac0-a718-24ca705cad22.<u></u>png</a><br>
(I'll upload the screenshot to somewhere else if anybody can't see it)<br>
The VisualVM instance is running on JDK6u26, with ParNew+CMS.<br>
In the screenshot, Visual GC reports that the old gen collection count is<br>
20, while JConsole reports 10.<br>
<br>
I see that there was this bug:<br>
6580448: CMS: Full GC collection count mismatch between<br>
GarbageCollectorMXBean and jvmstat (VisualGC)<br>
I don't think the current implementation has a bug in the sense that the two<br>
counters don't report the same number.<br>
<br>
This behavior seems reasonable, but the naming of the value in these tools<br>
are confusing: both tools say "collections", but apparently the number in<br>
Visual GC means "number of pauses" where as the number in JConsole means<br>
"number of collection cycles". It'd be great if the difference could be<br>
documented somewhere, if that's the intended behavior.<br>
<br>
And then the buggy behavior. Code demo posted on gist:<br>
<a href="https://gist.github.com/1106263" target="_blank">https://gist.github.com/<u></u>1106263</a><br>
Starting from JDK6u23, when using CMS without ExplicitGCInvokesConcurrent,<br>
System.gc() (or Runtime.getRuntime().gc(), or MemoryMXBean.gc() via JMX)<br>
would make the JMM GC counter increment by 2 per invocation, while the<br>
jvmstat counter is only incremented by 1. I believe the latter is correct<br>
and the former needs some fixing.<br>
<br>
==============================<u></u>=======================<br>
<br>
My understanding of the behavior shown above:<br>
<br>
1. The concurrent GC part:<br>
<br>
There are 2 pauses in a CMS concurrent GC cycle, one in the initial mark<br>
phase, and one in the final remark phase.<br>
To trigger a concurrent GC cycle, the CMS thread wakes up periodically to<br>
see if it shouldConcurrentCollect(), and trigger a cycle when the predicate<br>
returned true, or goes back to sleep if the predicate returned false. The<br>
whole concurrent GC cycle doesn't go through<br>
GenCollectedHeap::do_<u></u>collection().<br>
<br>
The jvmstat counter for old gen pauses is updated in<br>
CMSCollector::do_CMS_<u></u>operation(CMS_op_type op), which exactly covers both<br>
pause phases.<br>
<br>
The JMM counter, however, is updated in the concurrent sweep phase,<br>
CMSCollector::sweep(bool asynch), if there was no concurrent mode failure;<br>
or it is updated in CMSCollector::do_compaction_<u></u>work(bool<br>
clear_all_soft_refs) in case of a bailout due to concurrent mode failure<br>
(advertised as so in the code comments). So that's an increment by 1 per<br>
concurrent GC cycle, which does reflect the "number of collection cycles",<br>
fair enough.<br>
<br>
So far so good.<br>
<br>
2. The System.gc() part:<br>
<br>
Without ExplicitGCInvokesConcurrent set, System.gc() does a stop-the-world<br>
full GC, which consists of only one pause, so "number of pauses" would equal<br>
"number of collections" in this case.<br>
It will go into GenCollectedHeap::do_<u></u>collection(); both the jvmstat and the<br>
JMM GC counter gets incremented by 1 here,<br>
<br>
TraceCollectorStats tcs(_gens[i]->counters());<br>
TraceMemoryManagerStats tmms(_gens[i]->kind());<br>
<br>
But, drilling down into:<br>
_gens[i]->collect(full, do_clear_all_soft_refs, size, is_tlab);<br>
<br>
That'll eventually go into:<br>
CMSCollector::acquire_control_<u></u>and_collect(bool full, bool<br>
clear_all_soft_refs)<br>
<br>
System.gc() is user requested so that'll go further into mark-sweep-compact:<br>
CMSCollector::do_compaction_<u></u>work(bool clear_all_soft_refs)<br>
And here, it increments the JMM GC counter again (remember it was in the<br>
concurrent GC path too, to handle bailouts), even though this is still in<br>
the same collection. This leads to the "buggy behavior" mentioned earlier.<br>
<br>
The JMM GC counter wasn't added to CMS until this fix got in:<br>
6581734: CMS Old Gen's collection usage is zero after GC which is incorrect<br>
<br>
The code added to CMSCollector::do_compaction_<u></u>work() works fine in the<br>
concurrent GC path, but interacts badly with the original logic in<br>
GenCollectedHeap::do_<u></u>collection().<br>
<br>
==============================<u></u>=======================<br>
<br>
I thought all concurrent mode failures/interrupts come from<br>
GenCollectedHeap::do_<u></u>collection(). If that's the case, then it seems<br>
unnecessary to update the JMM GC counter in<br>
CMSCollector::do_compaction_<u></u>work(), simply removing it should fix the<br>
problem.<br>
<br>
With that, I'd purpose the following (XS) change: (diff against HS20)<br>
<br>
diff -r f0f676c5a2c6<br>
src/share/vm/gc_<u></u>implementation/<u></u>concurrentMarkSweep/<u></u>concurrentMarkSweepGeneration.<u></u>cpp<br>
---<br>
a/src/share/vm/gc_<u></u>implementation/<u></u>concurrentMarkSweep/<u></u>concurrentMarkSweepGeneration.<u></u>cpp<br>
Tue Mar 15 19:30:16 2011 -0700<br>
+++<br>
b/src/share/vm/gc_<u></u>implementation/<u></u>concurrentMarkSweep/<u></u>concurrentMarkSweepGeneration.<u></u>cpp<br>
Thu Jul 28 00:02:41 2011 +0800<br>
@@ -2022,9 +2022,6 @@<br>
<br>
_intra_sweep_estimate.padded_<u></u>average());<br>
}<br>
<br>
- {<br>
- TraceCMSMemoryManagerStats();<br>
- }<br>
GenMarkSweep::invoke_at_<u></u>safepoint(_cmsGen->level(),<br>
ref_processor(), clear_all_soft_refs);<br>
#ifdef ASSERT<br>
<br>
The same goes for the changes in:<br>
7036199: Adding a notification to the implementation of<br>
GarbageCollectorMXBeans<br>
<br>
==============================<u></u>=======================<br>
<br>
P.S. Is there an "official" name for the counters that I referred to as<br>
"jvmstat counters" above? Is it just jvmstat, or PerfData or HSPERFDATA?<br>
<br>
</blockquote>
<br>
</blockquote>
<br>
</div></div></blockquote></div><br>