Problem with Parnew GC

Fri Feb 3 10:25:57 PST 2012

Hi Pravah --

There was a bug fix for taking care of a fragmentation problem a while
back....

http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6999988

It may or may not be your problem (after all you do not get promotion
failures), but
it appears to me that it can result in very poor performance of the "local
free list caching"
and i can see it resulting in increased promotion times. I can't off the
top of
my head tell if there's a quick way of making that identification from your
6u20 JVM
but perhaps someone may have an idea.

As to whether allocating more memory to the JVM will help... If my
conjecture as to the
root cause is correct (and i will be the first to admit it might not be),
then, no: allocating
more heap will not help because the bug prevents the efficient use of
existing memory
rather than that existing memory is quickly used up; so the extra heap will
not help.

But as you can see I am doing a lot of hand-waving here, so you should
probably
follow up with Sun/Oracle JVM support.

-- ramki

On Fri, Feb 3, 2012 at 9:44 AM, pravah wordpress <pravah.wordpress at gmail.com
> wrote:

> Hi,
> It is not possible to check it with 1.6.0_29 as this is happening in
> production.
> Today we checked the iostat and sar output and found that there are no io
> waits and no swappings. Will allocating more memory to JVM (Total heap+ YG
> space ) solve this problem of slow response ? Is it normal to have 2 Parnew
> / second ?(and they are always taking > 0.1 Second)
>
> Thanks in advance.
> Pravah
>
>
>
> On Fri, Feb 3, 2012 at 11:58 AM, Srinivas Ramakrishna <ysr1729 at gmail.com>wrote:
>
>> Is it possible for you to check if this happens with 1.6.0_29 as well?
>>
>> -- ramki
>>
>> On Thu, Feb 2, 2012 at 9:30 AM, pravah wordpress <
>> pravah.wordpress at gmail.com> wrote:
>>
>>> Hi Team,
>>> For last couple of weeks, while monitoring production logs, we are
>>> seeing following 2 scenarios-
>>> 2012-01-30T09:45:57.783+0530: 211563.940: [GC 211563.941: [ParNew:
>>> 1695683K->20039K(1887488K), 0.1443767 secs] 2704741K->1029575K(5033216K),
>>> 0.1456574 secs] [Times: user=0.42 sys=0.02, real=0.15 secs]
>>> 2012-01-30T09:46:35.195+0530: 211601.351: [GC 211601.352: [ParNew:
>>> 1697863K->21131K(1887488K), 0.1623961 secs] 2707399K->1031401K(5033216K),
>>> 0.1636535 secs] [Times: user=0.41 sys=0.09, real=0.16 secs]
>>> 2012-01-30T09:47:15.555+0530: 211641.711: [GC 211641.712: [ParNew:
>>> 1698955K->19118K(1887488K), 0.1422631 secs] 2709225K->1030329K(5033216K),
>>> 0.1435373 secs] [Times: user=0.42 sys=0.01, real=0.14 secs]
>>> 2012-01-30T09:47:55.656+0530: 211681.811: [GC 211681.812: [ParNew:
>>> 1696942K->21437K(1887488K), 0.1340463 secs] 2708153K->1033449K(5033216K),
>>> 0.1352694 secs] [Times: user=0.40 sys=0.01, real=0.14 secs]
>>> 2012-01-30T09:48:29.406+0530: 211715.562: [GC 211715.564: [ParNew:
>>> 1699261K->18356K(1887488K), 0.1362798 secs] 2711273K->1031807K(5033216K),
>>> 0.1387961 secs] [Times: user=0.40 sys=0.03, real=0.14 secs]
>>> 2012-01-30T09:48:57.017+0530: 211743.172: [GC 211743.173: [ParNew:
>>> 1696035K->22375K(1887488K), 12.3948960 secs] 2709487K->1036955K(5033216K),
>>> 12.3962135 secs] [Times: *user=15.73 sys=0.60, real=12.40 secs]
>>> *2012-01-30T09:49:41.237+0530: 211787.392: [GC 211787.392: [ParNew:
>>> 1698873K->21698K(1887488K), 0.1251361 secs] 2713453K->1037007K(5033216K),
>>> 0.1262755 secs] [Times: user=0.39 sys=0.00, real=0.13 secs]
>>> 2012-01-30T09:50:24.348+0530: 211830.503: [GC 211830.504: [ParNew:
>>> 1699522K->21849K(1887488K), 0.1370179 secs] 2714831K->1037980K(5033216K),
>>> 0.1382479 secs] [Times: user=0.40 sys=0.01, real=0.14 secs]
>>> 2012-01-30T09:50:58.516+0530: 211864.670: [GC 211864.671: [ParNew:
>>> 1699673K->25281K(1887488K), 0.1334443 secs] 2715804K->1042397K(5033216K),
>>> 0.1347060 secs] [Times: user=0.43 sys=0.00, real=0.14 secs]
>>> 2012-01-30T09:51:33.830+0530: 211899.985: [GC 211899.985: [ParNew:
>>> 1695938K->28123K(1887488K), 0.1449732 secs] 2713054K->1046170K(5033216K),
>>> 0.1462090 secs] [Times: user=0.44 sys=0.01, real=0.15 secs]
>>>
>>> This is happening atleast once in a day and the real time is around 10 S.
>>>
>>> Another observation is as follows
>>>
>>> 2012-01-30T14:53:11.645+0530: 229997.686: [GC 229997.687: [ParNew:
>>> 1686605K->39956K(1887488K), 0.1504394 secs] 3258191K->1612228K(5033216K),
>>> 0.1516840 secs] [Times: user=0.47 sys=0.02, real=0.15 secs]
>>> 2012-01-30T14:53:45.006+0530: 230031.047: [GC 230031.048: [ParNew:
>>> 1717780K->30950K(1887488K), 0.1693496 secs] 3290052K->1604025K(5033216K),
>>> 0.1705586 secs] [Times: user=0.52 sys=0.04, real=0.17 secs]
>>> 2012-01-30T14:53:45.208+0530: 230031.249: [GC [1 CMS-initial-mark:
>>> 1573075K(3145728K)] 1608943K(5033216K), 0.4815794 secs] [Times: user=0.13
>>> sys=0.35, real=0.48 secs]
>>> 2012-01-30T14:53:45.692+0530: 230031.733: [CMS-concurrent-mark-start]
>>> 2012-01-30T14:53:52.114+0530: 230038.155: [CMS-concurrent-mark:
>>> 6.283/6.422 secs] [Times: user=11.70 sys=2.40, *real=6.42 secs*]
>>> 2012-01-30T14:53:52.115+0530: 230038.155: [CMS-concurrent-preclean-start]
>>> 2012-01-30T14:53:52.470+0530: 230038.510: [CMS-concurrent-preclean:
>>> 0.346/0.355 secs] [Times: user=0.45 sys=0.16, real=0.36 secs]
>>> 2012-01-30T14:53:52.470+0530: 230038.511:
>>> [CMS-concurrent-abortable-preclean-start]
>>>  CMS: abort preclean due to time 2012-01-30T14:53:57.500+0530:
>>> 230043.541: [CMS-concurrent-abortable-preclean: 4.906/5.030 secs] [Times:
>>> user=8.73 sys=0.62, *real=5.03 secs*]
>>> 2012-01-30T14:53:57.532+0530: 230043.573: [GC[YG occupancy: 839183 K
>>> (1887488 K)]230043.573: [Rescan (parallel) , 1.8934193 secs]230045.467:
>>> [weak refs processing, 0.0612851 secs] [1 CMS-remark: 1573075K(3145728K)]
>>> 2412258K(5033216K), 1.9618014 secs] [Times: user=5.58 sys=0.10, real=1.96
>>> secs]
>>> 2012-01-30T14:53:59.497+0530: 230045.538: [CMS-concurrent-sweep-start]
>>> 2012-01-30T14:54:08.616+0530: 230054.656: [CMS-concurrent-sweep:
>>> 8.635/9.118 secs] [Times: user=17.84 sys=2.36, *real=9.12 secs*]
>>> 2012-01-30T14:54:08.617+0530: 230054.657: [CMS-concurrent-reset-start]
>>> 2012-01-30T14:54:08.656+0530: 230054.696: [CMS-concurrent-reset:
>>> 0.039/0.039 secs] [Times: user=0.05 sys=0.00, real=0.04 secs]
>>> 2012-01-30T14:54:12.410+0530: 230058.451: [GC 230058.452: [ParNew:
>>> 1708774K->25197K(1887488K), 0.1436152 secs] 2456494K->773832K(5033216K),
>>> 0.1448754 secs] [Times: user=0.48 sys=0.01, real=0.15 secs]
>>> 2012-01-30T14:54:38.243+0530: 230084.284: [GC 230084.284: [ParNew:
>>> 1703021K->62457K(1887488K), 0.2070478 secs] 2451656K->811902K(5033216K),
>>> 0.2083137 secs] [Times: user=0.67 sys=0.01, real=0.21 secs]
>>>
>>>
>>> Here CMS concurrent mark and sweep and also remark is taking
>>> considerable time many time above 15 seconds. This also happens once in a
>>> day.
>>> Why is this happening ?
>>>
>>> Also no full GC is observed. Also Parnew is happening two times per
>>> second during peak load. Is this a cause of worry / slow performance ? This
>>> is OLTP app and no batch jobs are running.
>>> Following is the configuration
>>> Java HotSpot(TM) 64-Bit Server VM (16.3-b01) for solaris-sparc JRE
>>> (1.6.0_20-b02)
>>>
>>> -XX:+DisableExplicitGC
>>> -XX:-DoEscapeAnalysis
>>> -XX:InitialHeapSize=5368709120
>>> -XX:+LogVMOutput
>>> -XX:MaxHeapSize=5368709120
>>> -XX:MaxNewSize=2147483648
>>> -XX:MaxPermSize=536870912
>>> -XX:MaxTenuringThreshold=4
>>> -XX:NewRatio=3
>>> -XX:NewSize=2147483648
>>> -XX:ParallelGCThreads=4
>>> -XX:PermSize=536870912
>>> -XX:+PrintCommandLineFlags
>>> -XX:+PrintGC
>>> -XX:+PrintGCDateStamps
>>> -XX:+PrintGCDetails
>>> -XX:+PrintGCTimeStamps
>>> -XX:ThreadStackSize=256
>>> -XX:+TraceClassUnloading
>>> -XX:+UnlockDiagnosticVMOptions
>>> -XX:+UseConcMarkSweepGC
>>> -XX:+UseParNewGC
>>>
>>> Thanks in advance,
>>> Pravah.
>>>
>>> _______________________________________________
>>> hotspot-gc-use mailing list
>>> hotspot-gc-use at openjdk.java.net
>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>>
>>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120203/ad852e7f/attachment.html 