Right, it's a bug for CMS to cause a full gc for perm gen expansion. There were a couple of releases in 6uXX (for a suitable value of hsXX)<br>where this regression had crept in unnoticed until it was noticed and fixed. Try the more recent 7uXX (pre-perm gen removal changes) where you should<br>
find the perm gen expand without a stop-world full gc (and may be trigger a CMS concurrent cycle instead, memory is hazy and<br>the source code not close at hand). As you guys noted the workaround is to max-size the perm gen and enable class unloading.<br>
<br>-- ramki<br><br><div class="gmail_quote">On Thu, Sep 13, 2012 at 10:09 PM, Charlie Hunt <span dir="ltr"><<a href="mailto:chunt@salesforce.com" target="_blank">chunt@salesforce.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<div style="word-wrap:break-word">Hi Jon,<div><br></div><div>As often is the case, thanks for confirming my suspicions!</div><div><br></div><div>Increasing PermSize is definitely in order. :-)</div><div><br></div><div>thanks again,</div>
<div><br></div><div>charlie ...</div><div><div class="h5"><div><br><div><div>On Sep 13, 2012, at 2:37 PM, Jon Masamitsu wrote:</div><br><blockquote type="cite">
<div bgcolor="#FFFFFF" text="#000000">
Charlie,<br>
<br>
It is probably a case of mislabeling. I think in earlier<br>
releases we were just dumbly labeling any full GC as<br>
a concurrent mode failure. But it is a concurrent mode<br>
failure if the perm gen fills up. Ramki had done some<br>
work to start a concurrent collection for perm gen with<br>
a different trigger.<br>
<br>
Increase your PermSize so that we don't have to look<br>
at it :-).<br>
<br>
Jon<br>
<br>
<br>
On 09/13/12 11:26, Charlie Hunt wrote:
<blockquote type="cite">I'm looking at a GC log and surprised by the
"concurrent mode failure" messages.
<div><br>
</div>
<div>I'm seeing the following GC log entries as the first 8 GCs: </div>
<div>
<div><br>
</div>
<div>3.398: [Full GC 3.398: [CMS (concurrent mode failure)[YG
occupancy: 594957 K (1887488 K)]3.489: [weak refs processing,
0.0000140 secs]: 0K->0K(6291456K), 0.1308660 secs]
594957K->594957K(8178944K), [CMS Perm :
21247K->21247K(21248K)], 0.1310260 secs] [Times: user=0.13
sys=0.03, real=0.14 secs]</div>
<div><br>
</div>
<div>3.529: [Full GC 3.529: [CMS (concurrent mode failure)[YG
occupancy: 594957 K (1887488 K)]3.617: [weak refs processing,
0.0000110 secs]: 0K->0K(6291456K), 0.1010290 secs]
594957K->594957K(8178944K), [CMS Perm :
21248K->21248K(42496K)], 0.1011530 secs] [Times: user=0.12
sys=0.00, real=0.10 secs]</div>
<div><br>
</div>
<div>3.638: [Full GC 3.638: [CMS (concurrent mode failure)[YG
occupancy: 662071 K (1887488 K)]3.730: [weak refs processing,
0.0000140 secs]: 0K->0K(6291456K), 0.1068710 secs]
662071K->662071K(8178944K), [CMS Perm :
21319K->21319K(42688K)], 0.1069610 secs] [Times: user=0.15
sys=0.00, real=0.11 secs]</div>
<div><br>
</div>
<div>3.772: [Full GC 3.772: [CMS (concurrent mode failure)[YG
occupancy: 729184 K (1887488 K)]3.915: [weak refs processing,
0.0000140 secs]: 0K->0K(6291456K), 0.1582170 secs]
729184K->729184K(8178944K), [CMS Perm :
21499K->21499K(42880K)], 0.1583500 secs] [Times: user=0.20
sys=0.00, real=0.16 secs]</div>
<div><br>
</div>
<div>3.962: [Full GC 3.962: [CMS (concurrent mode failure)[YG
occupancy: 804686 K (1887488 K)]4.107: [weak refs processing,
0.0000130 secs]: 0K->0K(6291456K), 0.1598050 secs]
804686K->804686K(8178944K), [CMS Perm :
21702K->21702K(43072K)], 0.1599420 secs] [Times: user=0.21
sys=0.00, real=0.16 secs]</div>
<div><br>
</div>
<div>4.497: [Full GC 4.497: [CMS (concurrent mode failure)[YG
occupancy: 939150 K (1887488 K)]4.672: [weak refs processing,
0.0000130 secs]: 0K->0K(6291456K), 0.1895350 secs]
939150K->939150K(8178944K), [CMS Perm :
22202K->22202K(43408K)], 0.1896680 secs] [Times: user=0.23
sys=0.00, real=0.19 secs]</div>
<div><br>
</div>
<div>5.054: [Full GC 5.054: [CMS (concurrent mode failure)[YG
occupancy: 992483 K (1887488 K)]5.274: [weak refs processing,
0.0000130 secs]: 0K->0K(6291456K), 0.2347170 secs]
992483K->992483K(8178944K), [CMS Perm :
24058K->24058K(44408K)], 0.2348700 secs] [Times: user=0.28
sys=0.00, real=0.23 secs]</div>
<div><br>
</div>
<div>6.662: [Full GC 6.662: [CMS (concurrent mode failure)[YG
occupancy: 1292895 K (1887488 K)]6.953: [weak refs processing,
0.0000140 secs]: 0K->0K(6291456K), 0.3063690 secs]
1292895K->1292895K(8178944K), [CMS Perm :
30692K->30692K(48120K)], 0.3065860 secs] [Times: user=0.66
sys=0.01, real=0.30 secs]</div>
</div>
<div><br>
</div>
<div>After these 8 GCs, the GC log is much inline with what I'd
expect, i.e. ParNew GCs, initial-marks, remarks, etc.</div>
<div><br>
</div>
<div>In each of the above GCs:</div>
<div>- young gen is increasing in occupancy</div>
<div>- old gen remains empty</div>
<div>- perm gen space size is expanding</div>
<div><br>
</div>
<div>I can understand the Full GC being reported since perm gen is
expanding, but I don't understand the reporting of "concurrent
mode failure". Am I missing something? Is it possible HotSpot
is reporting concurrent mode failure when perm gen is expanding?</div>
<div><br>
</div>
<div>Here's the set of command line options in use:</div>
<div><span style="text-indent:0px;letter-spacing:normal;font-variant:normal;text-align:-webkit-auto;font-style:normal;display:inline!important;font-weight:normal;float:none;line-height:15px;color:rgb(34,34,34);text-transform:none;font-size:12px;white-space:normal;font-family:arial,helvetica,clean,sans-serif;word-spacing:0px">-Xmx8G -Xms8G -Xmn1500m
-XX:+UseCompressedOops -XX:-UseGCOverheadLimit
-XX:+UseConcMarkSweepGC -XX:MaxDirectMemorySize=5000m</span></div>
<div><br>
</div>
<div>thanks,</div>
<div><br>
</div>
<div>charlie ...</div>
<div><br>
</div>
<div>PS: I didn't go look at / investigate OpenJDK HotSpot source
code since this is JDK 6u21 and thought it might be possible
something may have changed between 6u21 and what's in OpenJDK.</div>
<div><br>
</div>
</blockquote>
</div>
</blockquote></div><br></div></div></div></div></blockquote></div><br>