<div dir="ltr"><div>Hi,</div><div> </div><div>When setting Xms != Xmx (yes, I know this is a bad idea...) I've seen a peculiar behavior with a constant increase of old generation capacity prior to CMS but without a FullGC event. These are the settings which the application is running on:</div>
<div> </div><div>-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintTenuringDistribution -Xloggc:/tmp/gc_logs.txt -XX:+AggressiveOpts -XX:+UseBiasedLocking -XX:CompileThreshold=5000 -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseParNewGC -Xss2048k -Xmx1024M -Xms512M -Xmn160M</div>
<div> </div><div> </div><div>Below we have two examples of initiating CMS cycles. Prior to CMS running the heap is in total 507904K (first example) but suddenly after the initial mark the capacity increased by 192K. This pattern is pretty consistent throughout the execution.</div>
<div> </div><div> </div><div>2014-02-27T17:54:33.554+0100: 3209.911: [GC2014-02-27T17:54:33.554+0100: 3209.912: [ParNew<br>Desired survivor size 8388608 bytes, new threshold 6 (max 6)<br>- age 1: 1531520 bytes, 1531520 total<br>
- age 3: 160 bytes, 1531680 total<br>: 132721K->2333K(147456K), 0.0123744 secs] 289498K->159110K(<strong>507904K</strong>), 0.0129755 secs] [Times: user=0.13 sys=0.01, real=0.01 secs]<br>2014-02-27T17:54:33.567+0100: 3209.925: Total time for which application threads were stopped: 0.0272471 seconds<br>
2014-02-27T17:54:33.706+0100: 3210.064: Total time for which application threads were stopped: 0.0133765 seconds<br>2014-02-27T17:54:33.726+0100: 3210.084: Total time for which application threads were stopped: 0.0197027 seconds<br>
2014-02-27T17:54:33.739+0100: 3210.097: [GC [1 CMS-initial-mark: 156777K(<strong><u>360640K</u></strong>)] 290183K(<strong>508096K</strong>), 1.8524057 secs] [Times: user=1.85 sys=0.00, real=1.85 secs]<br></div><div> </div>
<div>2014-02-27T19:07:07.828+0100: 7564.088: [GC2014-02-27T19:07:07.828+0100: 7564.089: [ParNew<br>Desired survivor size 8388608 bytes, new threshold 6 (max 6)<br>- age 1: 1705520 bytes, 1705520 total<br>- age 4: 32 bytes, 1705552 total<br>
- age 5: 64 bytes, 1705616 total<br>- age 6: 32 bytes, 1705648 total<br>: 132729K->2201K(147456K), 0.0154973 secs] 289657K->159130K(<strong>508096K</strong>), 0.0161130 secs] [Times: user=0.14 sys=0.00, real=0.02 secs]<br>
2014-02-27T19:07:07.845+0100: 7564.105: Total time for which application threads were stopped: 0.0318814 seconds<br>2014-02-27T19:07:08.005+0100: 7564.265: Total time for which application threads were stopped: 0.0153855 seconds<br>
2014-02-27T19:07:08.027+0100: 7564.287: Total time for which application threads were stopped: 0.0217859 seconds<br>2014-02-27T19:07:08.049+0100: 7564.309: Total time for which application threads were stopped: 0.0218527 seconds<br>
2014-02-27T19:07:08.063+0100: 7564.324: [GC [1 CMS-initial-mark: 156929K(<strong><u>361024K</u></strong>)] 290203K(<strong>508480K</strong>), 1.8475537 secs] [Times: user=1.85 sys=0.00, real=1.85 secs]<br></div><div> </div>
<div> </div><div><div>The question is why does the heap grow like this? I was under the impression that CMS only increased the capacity using a FullGC event, and by then increased more than a few hundred kilobytes. What I've also experienced is that the when the heap is NOT increased, then the pause is considerably lower (as shown below). Is it possible that this minor heap growth is adding adding to the pause of the initial mark?</div>
<div> </div><div> </div></div><div><font color="#000000" face="Times New Roman">
</font><p style="margin-bottom:12pt"><span style="font-family:"Helvetica","sans-serif""><font color="#000000">2014-02-28T07:32:21.878+0100:
52277.150: [GC2014-02-28T07:32:21.878+0100: 52277.151: [ParNew<br>
Desired survivor size 8388608 bytes, new threshold 6 (max 6)<br>
- age 1: 1021256 bytes, 1021256
total<br>
- age 2: 32
bytes, 1021288 total<br>
- age 5: 32
bytes, 1021320 total<br>
: 132007K->1234K(147456K), 0.0123908 secs] 284921K->154148K(<strong>510400K</strong>),
0.0129916 secs] [Times: user=0.13 sys=0.01, real=0.01 secs]<br>
2014-02-28T07:32:21.891+0100: 52277.164: Total time for which application
threads were stopped: 0.0279730 seconds<br>
2014-02-28T07:32:21.906+0100: 52277.179: [GC [1 CMS-initial-mark:
152913K(362944K)] 155041K(<strong>510400K</strong>), 0.0365786 secs] [Times: user=0.04 sys=0.00,
real=0.04 secs]</font></span></p><font color="#000000" size="3" face="Times New Roman">
</font></div><div> </div><div> </div><div> </div><div>Best Regards,</div><div> </div><div>Gustav Åkesson</div></div>