jdk 1.4.2_17 promotion failure (fragmentation?)
Mike Finn
mike at mikefinn.com
Mon Aug 11 20:09:07 PDT 2008
Here is a bit more of the log before the failure. We have a process
monitor that restarts the server if it becomes unresponsive, so the STW
GC usually doesn't log out its completion, because the server has been
restarted.
The promotion failure/concurrent mode failure usually happens after
running for several days, but it has happened after only running a few
hours.
265131.419: [GC {Heap before GC invocations=57320:
Heap
par new generation total 294912K, used 285715K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 100% used [0xfffffffbef000000, 0xfffffffbff000000,
0xfffffffbff000000)
from space 32768K, 71% used [0xfffffffbff000000, 0xfffffffc00704cc8,
0xfffffffc01000000)
to space 32768K, 0% used [0xfffffffc01000000, 0xfffffffc01000000,
0xfffffffc03000000)
concurrent mark-sweep generation total 14352384K, used 11590395K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
265131.421: [ParNew
Desired survivor size 16777216 bytes, new threshold 1 (max 5)
- age 1: 23454432 bytes, 23454432 total
- age 2: 8152032 bytes, 31606464 total
: 285715K->31114K(294912K), 0.3236327 secs]
11876110K->11629279K(14647296K) Heap after GC invocations=57321:
Heap
par new generation total 294912K, used 31114K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 0% used [0xfffffffbef000000, 0xfffffffbef000000,
0xfffffffbff000000)
from space 32768K, 94% used [0xfffffffc01000000, 0xfffffffc02e62938,
0xfffffffc03000000)
to space 32768K, 0% used [0xfffffffbff000000, 0xfffffffbff000000,
0xfffffffc01000000)
concurrent mark-sweep generation total 14352384K, used 11598165K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
} , 0.3262163 secs]
265134.554: [GC {Heap before GC invocations=57321:
Heap
par new generation total 294912K, used 293258K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 100% used [0xfffffffbef000000, 0xfffffffbff000000,
0xfffffffbff000000)
from space 32768K, 94% used [0xfffffffc01000000, 0xfffffffc02e62938,
0xfffffffc03000000)
to space 32768K, 0% used [0xfffffffbff000000, 0xfffffffbff000000,
0xfffffffc01000000)
concurrent mark-sweep generation total 14352384K, used 11598165K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
265134.556: [ParNew
Desired survivor size 16777216 bytes, new threshold 1 (max 5)
- age 1: 17172968 bytes, 17172968 total
: 293258K->16901K(294912K), 0.4933607 secs]
11891423K->11639137K(14647296K) Heap after GC invocations=57322:
Heap
par new generation total 294912K, used 16901K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 0% used [0xfffffffbef000000, 0xfffffffbef000000,
0xfffffffbff000000)
from space 32768K, 51% used [0xfffffffbff000000, 0xfffffffc00081530,
0xfffffffc01000000)
to space 32768K, 0% used [0xfffffffc01000000, 0xfffffffc01000000,
0xfffffffc03000000)
concurrent mark-sweep generation total 14352384K, used 11622236K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
} , 0.4961586 secs]
265137.224: [GC {Heap before GC invocations=57322:
Heap
par new generation total 294912K, used 279045K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 100% used [0xfffffffbef000000, 0xfffffffbff000000,
0xfffffffbff000000)
from space 32768K, 51% used [0xfffffffbff000000, 0xfffffffc00081530,
0xfffffffc01000000)
to space 32768K, 0% used [0xfffffffc01000000, 0xfffffffc01000000,
0xfffffffc03000000)
concurrent mark-sweep generation total 14352384K, used 11622236K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
265137.226: [ParNew
Desired survivor size 16777216 bytes, new threshold 5 (max 5)
- age 1: 11870696 bytes, 11870696 total
: 279045K->11695K(294912K), 0.3247989 secs]
11901281K->11645944K(14647296K) Heap after GC invocations=57323:
Heap
par new generation total 294912K, used 11695K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 0% used [0xfffffffbef000000, 0xfffffffbef000000,
0xfffffffbff000000)
from space 32768K, 35% used [0xfffffffc01000000, 0xfffffffc01b6bda8,
0xfffffffc03000000)
to space 32768K, 0% used [0xfffffffbff000000, 0xfffffffbff000000,
0xfffffffc01000000)
concurrent mark-sweep generation total 14352384K, used 11634249K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
} , 0.3275647 secs]
265139.683: [GC {Heap before GC invocations=57323:
Heap
par new generation total 294912K, used 273839K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 100% used [0xfffffffbef000000, 0xfffffffbff000000,
0xfffffffbff000000)
from space 32768K, 35% used [0xfffffffc01000000, 0xfffffffc01b6bda8,
0xfffffffc03000000)
to space 32768K, 0% used [0xfffffffbff000000, 0xfffffffbff000000,
0xfffffffc01000000)
concurrent mark-sweep generation total 14352384K, used 11634249K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
265139.686: [ParNew
Desired survivor size 16777216 bytes, new threshold 2 (max 5)
- age 1: 15240960 bytes, 15240960 total
- age 2: 8310352 bytes, 23551312 total
: 273839K->23159K(294912K), 0.2782267 secs]
11908088K->11657408K(14647296K) Heap after GC invocations=57324:
Heap
par new generation total 294912K, used 23159K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 0% used [0xfffffffbef000000, 0xfffffffbef000000,
0xfffffffbff000000)
from space 32768K, 70% used [0xfffffffbff000000, 0xfffffffc0069ddd8,
0xfffffffc01000000)
to space 32768K, 0% used [0xfffffffc01000000, 0xfffffffc01000000,
0xfffffffc03000000)
concurrent mark-sweep generation total 14352384K, used 11634249K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
} , 0.2810588 secs]
265140.358: [CMS-concurrent-mark: 371.391/427.845 secs]
265140.358: [CMS-concurrent-preclean-start]
265142.278: [GC {Heap before GC invocations=57324:
Heap
par new generation total 294912K, used 284950K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 99% used [0xfffffffbef000000, 0xfffffffbfefa7bf0,
0xfffffffbff000000)
from space 32768K, 70% used [0xfffffffbff000000, 0xfffffffc0069ddd8,
0xfffffffc01000000)
to space 32768K, 0% used [0xfffffffc01000000, 0xfffffffc01000000,
0xfffffffc03000000)
concurrent mark-sweep generation total 14352384K, used 11634249K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
265142.280: [ParNew
Desired survivor size 16777216 bytes, new threshold 2 (max 5)
- age 1: 13342736 bytes, 13342736 total
- age 2: 10303256 bytes, 23645992 total
: 284950K->23261K(294912K), 0.3157337 secs]
11919199K->11664877K(14647296K) Heap after GC invocations=57325:
Heap
par new generation total 294912K, used 23261K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 0% used [0xfffffffbef000000, 0xfffffffbef000000,
0xfffffffbff000000)
from space 32768K, 70% used [0xfffffffc01000000, 0xfffffffc026b7648,
0xfffffffc03000000)
to space 32768K, 0% used [0xfffffffbff000000, 0xfffffffbff000000,
0xfffffffc01000000)
concurrent mark-sweep generation total 14352384K, used 11641615K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
} , 0.3180824 secs]
265145.240: [GC {Heap before GC invocations=57325:
Heap
par new generation total 294912K, used 285405K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 100% used [0xfffffffbef000000, 0xfffffffbff000000,
0xfffffffbff000000)
from space 32768K, 70% used [0xfffffffc01000000, 0xfffffffc026b7648,
0xfffffffc03000000)
to space 32768K, 0% used [0xfffffffbff000000, 0xfffffffbff000000,
0xfffffffc01000000)
concurrent mark-sweep generation total 14352384K, used 11641615K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
265145.242: [ParNew
Desired survivor size 16777216 bytes, new threshold 1 (max 5)
- age 1: 21400416 bytes, 21400416 total
- age 2: 8054280 bytes, 29454696 total
: 285405K->28990K(294912K), 0.3531017 secs]
11927021K->11680648K(14647296K) Heap after GC invocations=57326:
Heap
par new generation total 294912K, used 28990K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 0% used [0xfffffffbef000000, 0xfffffffbef000000,
0xfffffffbff000000)
from space 32768K, 88% used [0xfffffffbff000000, 0xfffffffc00c4fa18,
0xfffffffc01000000)
to space 32768K, 0% used [0xfffffffc01000000, 0xfffffffc01000000,
0xfffffffc03000000)
concurrent mark-sweep generation total 14352384K, used 11651657K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
} , 0.3555513 secs]
265147.633: [GC {Heap before GC invocations=57326:
Heap
par new generation total 294912K, used 291134K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 100% used [0xfffffffbef000000, 0xfffffffbff000000,
0xfffffffbff000000)
from space 32768K, 88% used [0xfffffffbff000000, 0xfffffffc00c4fa18,
0xfffffffc01000000)
to space 32768K, 0% used [0xfffffffc01000000, 0xfffffffc01000000,
0xfffffffc03000000)
concurrent mark-sweep generation total 14352384K, used 11651657K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
265147.635: [ParNew
Desired survivor size 16777216 bytes, new threshold 5 (max 5)
- age 1: 11786104 bytes, 11786104 total
: 291134K->11607K(294912K), 0.4969958 secs]
11942792K->11688180K(14647296K) Heap after GC invocations=57327:
Heap
par new generation total 294912K, used 11607K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 0% used [0xfffffffbef000000, 0xfffffffbef000000,
0xfffffffbff000000)
from space 32768K, 35% used [0xfffffffc01000000, 0xfffffffc01b55cf0,
0xfffffffc03000000)
to space 32768K, 0% used [0xfffffffbff000000, 0xfffffffbff000000,
0xfffffffc01000000)
concurrent mark-sweep generation total 14352384K, used 11676573K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
} , 0.4998969 secs]
265150.609: [GC {Heap before GC invocations=57327:
Heap
par new generation total 294912K, used 273751K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 100% used [0xfffffffbef000000, 0xfffffffbff000000,
0xfffffffbff000000)
from space 32768K, 35% used [0xfffffffc01000000, 0xfffffffc01b55cf0,
0xfffffffc03000000)
to space 32768K, 0% used [0xfffffffbff000000, 0xfffffffbff000000,
0xfffffffc01000000)
concurrent mark-sweep generation total 14352384K, used 11676573K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
265150.611: [ParNew
Desired survivor size 16777216 bytes, new threshold 2 (max 5)
- age 1: 11435216 bytes, 11435216 total
- age 2: 8139232 bytes, 19574448 total
: 273751K->19272K(294912K), 0.2576767 secs]
11950324K->11695845K(14647296K) Heap after GC invocations=57328:
Heap
par new generation total 294912K, used 19272K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 0% used [0xfffffffbef000000, 0xfffffffbef000000,
0xfffffffbff000000)
from space 32768K, 58% used [0xfffffffbff000000, 0xfffffffc002d21b0,
0xfffffffc01000000)
to space 32768K, 0% used [0xfffffffc01000000, 0xfffffffc01000000,
0xfffffffc03000000)
concurrent mark-sweep generation total 14352384K, used 11676573K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
} , 0.2600295 secs]
265152.992: [GC {Heap before GC invocations=57328:
Heap
par new generation total 294912K, used 281416K [0xfffffffbef000000,
0xfffffffc03000000, 0xfffffffc03000000)
eden space 262144K, 100% used [0xfffffffbef000000, 0xfffffffbff000000,
0xfffffffbff000000)
from space 32768K, 58% used [0xfffffffbff000000, 0xfffffffc002d21b0,
0xfffffffc01000000)
to space 32768K, 0% used [0xfffffffc01000000, 0xfffffffc01000000,
0xfffffffc03000000)
concurrent mark-sweep generation total 14352384K, used 11676573K
[0xfffffffc03000000, 0xffffffff6f000000, 0xffffffff6f000000)
concurrent-mark-sweep perm gen total 98304K, used 67646K
[0xffffffff6f000000, 0xffffffff75000000, 0xffffffff75000000)
265152.994: [ParNew (promotion failed)
Desired survivor size 16777216 bytes, new threshold 2 (max 5)
- age 1: 15741536 bytes, 15741536 total
- age 2: 7459336 bytes, 23200872 total
: 281416K->281416K(294912K), 2.7625640 secs]265155.757: [CMS265176.917:
[CMS-concurrent-preclean: 30.615/36.559 secs]
(concurrent mode failure)[Unloading class
sun.reflect.GeneratedSerializationConstructorAccessor193]
[Unloading class sun.reflect.GeneratedConstructorAccessor127]
[Unloading class sun.reflect.GeneratedMethodAccessor54]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor166]
[Unloading class sun.reflect.GeneratedMethodAccessor100]
Jones, Doug H wrote:
> That's odd ... could you send more of the GC details from around the
> conc-mode-failure, say some ParNew's just prior to it, and the start of
> the CMS GC, then through to the end of the CMS GC sequence.
>
> Thanks,
> Doug.
>
> -----Original Message-----
> From: Mike Finn [mailto:mike at mikefinn.com]
> Sent: Tuesday, 12 August 2008 7:28 a.m.
> To: hotspot-gc-use at openjdk.java.net
> Cc: Jones, Doug H
> Subject: Re: jdk 1.4.2_17 promotion failure (fragmentation?)
>
> Thanks for the reply. We had considered that, but, if I'm reading our
> logs correctly, it seems that CMS is started pretty close to 70 every
> time: ( here's a snippet of our CMS initial marks)
>
> 144975.040: [GC [1 CMS-initial-mark: 10047659K(14352384K)]
> 10064265K(14647296K), 0.1464111 secs]
> 147242.326: [GC [1 CMS-initial-mark: 10057190K(14352384K)]
> 10081419K(14647296K), 0.1732362 secs]
> 149781.334: [GC [1 CMS-initial-mark: 10050150K(14352384K)]
> 10063772K(14647296K), 0.1149508 secs]
> 155416.122: [GC [1 CMS-initial-mark: 10048398K(14352384K)]
> 10065437K(14647296K), 0.1324914 secs]
> 162762.754: [GC [1 CMS-initial-mark: 10047344K(14352384K)]
> 10063850K(14647296K), 0.1310949 secs]
>
>
> Jones, Doug H wrote:
>
>> Hi Mike,
>>
>> It is likely to be due to fragmentation of tenured (a CMS GC does not
>> compact tenured). Under the 1.4.2 the 'New Generation Guarantee'
>> requires that when a scavenge occurs there is contiguous space
>> available in tenured equal to the size of the New area (5.0 relaxes
>> that to just being enough space available, not necessarily
>>
> contiguous).
>
>> The fix is easy: you are half-way there with setting
>> -XX:CMSInitiatingOccupancyFraction=70. However to tell the JVM to take
>>
>
>
>> notice of it you also need to add -XX:+UseCMSInitiatingOccupancyOnly,
>> then CMS Collections will always kick in when tenured is approx 70%
>> full. I would suspect that currently they don't until tenured is well
>> above 90% full (1.4.2 is more optimistic I think than 5.0 about its
>> ability to schedule a CMS GC 'JIT with a bit to spare', but
>> conc-mode-failures can still be a problem under 5.0).
>>
>> Doug.
>>
>>
>> <snip>
>>
>>
>>
>
>
>
More information about the hotspot-gc-use
mailing list