Promotion failed caused full GC instead of normal GC hit in before
843829Aug 24 2007 — edited Sep 5 2007Hi
I have an issue where i would suspect the full GC should happen instead of the new GC makes the work. The problem is that we have to use the low pause GC to avoid long pause times, but this took 157secs, which of course blows of our API.
We use RedHat Enterprise 3.2(or 4 cant remember) JDK1.6u2b05, with the following options: -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xmx1536 and -Xss1024 -XX:+UseConcMarkSweepGC -XX:+DisableExplicitGC.
What i discovered, then at the beginning CMS was made every 100-120secs, it didnt happen later on for almost 2 hours. Of course that doesnt mean anything, but im sure it should have happened at the issued place, where it didnt happen for almost an hour:
109079.892: [GC 109079.892: [ParNew: 57090K->4708K(59008K), 0.0321350 secs] 1435428K->1383867K(1561568K), 0.0322990 secs]
109081.381: [GC 109081.381: [ParNew: 57188K->5632K(59008K), 0.0436920 secs] 1436347K->1385528K(1562336K), 0.0438620 secs]
109083.700: [GC 109083.700: [ParNew: 58112K->4648K(59008K), 0.0641520 secs] 1438008K->1385205K(1562848K), 0.0643150 secs]
109088.108: [GC 109088.108: [ParNew: 57128K->5583K(59008K), 0.0461920 secs] 1437685K->1386968K(1563616K), 0.0464030 secs]
109094.092: [GC 109094.092: [ParNew: 58063K->5138K(59008K), 0.0329350 secs] 1439448K->1387419K(1564384K), 0.0331000 secs]
109096.747: [GC 109096.747: [ParNew: 57618K->4172K(59008K), 0.0879320 secs] 1439899K->1387300K(1565152K), 0.0880990 secs]
109099.047: [GC 109099.047: [ParNew: 56652K->4051K(59008K), 0.0777350 secs] 1439780K->1388057K(1565792K), 0.0778960 secs]
109104.114: [GC 109104.114: [ParNew (promotion failed): 56528K->56528K(59008K), 0.0798210 secs]109104.194: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor288]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor261]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor279]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor94]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor339]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor322]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor355]
[Unloading class sun.reflect.GeneratedConstructorAccessor51]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor341]
.
.
.
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor328]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor271]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor326]
: 1384733K->167157K(1507328K), 157.2811760 secs] 1440534K->167157K(1566336K), 157.3655350 secs]
.
.
.
and in the end (we had to restart the component):
Heap
par new generation total 59008K, used 8697K [0x4fea0000, 0x53ea0000, 0x53ea0000)
eden space 52480K, 4% used [0x4fea0000, 0x500be780, 0x531e0000)
from space 6528K, 100% used [0x53840000, 0x53ea0000, 0x53ea0000)
to space 6528K, 0% used [0x531e0000, 0x531e0000, 0x53840000)
concurrent mark-sweep generation total 1507328K, used 211737K [0x53ea0000, 0xafea0000, 0xafea0000)
concurrent-mark-sweep perm gen total 27036K, used 15726K [0xafea0000, 0xb1907000, 0xb3ea0000)
So what i saw is that
1. there was enough garbage since it free up 1.3G
2. parnew GC has done the work instead of concurrent GC, i guess it is not concurrent in this case, which is not good for us
3. i have not found reasonable explanation what unloading.. means, only that i dont have to worry about it. Now, i do since it has never done that before, only when the issue happened. can anyone tell me why does that happen, and if that has any connection with the issue?
4. what should i do so the concurrent GC prevents this?
thanx
matra