Problem with Parnew GC

Fri Feb 3 09:44:23 PST 2012

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/ffa95cb1/attachment-0001.html 