Problem with Parnew GC

Sun Feb 5 08:57:26 PST 2012

Hi Ramki,
Thank you for your reply. I checked the given bug but it seems that it may
not be the root
cause as no promotion failures are happening in our case.
I think we will try with different values for new memory and see if it
improves the performance.
I shall post the results of our experiments.
Thanks again.
Pravah

On Fri, Feb 3, 2012 at 11:55 PM, Srinivas Ramakrishna <ysr1729 at gmail.com>wrote:

> 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/20120205/7f0054b7/attachment.html 