Long Parnew pause
Gustav Åkesson
gustav.r.akesson at gmail.com
Wed Feb 1 14:44:08 UTC 2017
Hi,
In our application I've observed an occasional and peculiar Parnew GC which
takes several seconds. From what I've been able to gather, it is associated
with an occasional 35mb allocation of data. Those objects are allocated and
tenured (see the bold aging in below logs) and once being promoted to old
generation, that Parnew GC takes around 7 seconds. This surprises me a bit
since it should not take so long time to move 35mb of data to another heap
region.
Looking at the logs, this issue is not related to I/O (zero systime) nor
TTSP (takes few millis to stop the application threads). GC threads seems
to simply spend their time working on the CPU chip. What in Parnew/CMS
could possibly make these 35mb take so long to promote? Some flags that can
shed som light, or any suspicion such as free-list balancing?
I appreciate any input on the matter.
JVM settings and platform information at the end of this mail.
{Heap before GC invocations=1723 (full 0):
par new generation total 1887488K, used 1768096K [0x00007fccf1600000,
0x00007fcd71600000, 0x00007fcd71600000)
eden space 1677824K, 100% used [0x00007fccf1600000, 0x00007fcd57c80000,
0x00007fcd57c80000)
from space 209664K, 43% used [0x00007fcd64940000, 0x00007fcd6a1680e8,
0x00007fcd71600000)
to space 209664K, 0% used [0x00007fcd57c80000, 0x00007fcd57c80000,
0x00007fcd64940000)
concurrent mark-sweep generation total 34973696K, used 7319028K
[0x00007fcd71600000, 0x00007fd5c8000000, 0x00007fd5c8000000)
Metaspace used 121299K, capacity 134343K, committed 134400K,
reserved 135168K
2017-01-26T12:50:11.476+0100: 14135.489: [GC (Allocation Failure)
2017-01-26T12:50:11.476+0100: 14135.489: [ParNew
Desired survivor size 107347968 bytes, new threshold 6 (max 6)
- age 1: 12439600 bytes, 12439600 total
- age 2: 5233256 bytes, 17672856 total
- age 3: 5083408 bytes, 22756264 total
*- age 4: 37639936 bytes, 60396200 total*
- age 5: 4869520 bytes, 65265720 total
- age 6: 4746784 bytes, 70012504 total
: 1768096K->91122K(1887488K), 0.1117876 secs]
9087124K->7412981K(36861184K), 0.1120711 secs] [Times: user=0.85 sys=0.00,
real=0.11 secs]
Heap after GC invocations=1724 (full 0):
par new generation total 1887488K, used 91122K [0x00007fccf1600000,
0x00007fcd71600000, 0x00007fcd71600000)
eden space 1677824K, 0% used [0x00007fccf1600000, 0x00007fccf1600000,
0x00007fcd57c80000)
from space 209664K, 43% used [0x00007fcd57c80000, 0x00007fcd5d57ca70,
0x00007fcd64940000)
to space 209664K, 0% used [0x00007fcd64940000, 0x00007fcd64940000,
0x00007fcd71600000)
concurrent mark-sweep generation total 34973696K, used 7321858K
[0x00007fcd71600000, 0x00007fd5c8000000, 0x00007fd5c8000000)
Metaspace used 121299K, capacity 134343K, committed 134400K,
reserved 135168K
}
2017-01-26T12:50:11.589+0100: 14135.601: Total time for which application
threads were stopped: 0.1174674 seconds, Stopping threads took: 0.0042340
seconds
2017-01-26T12:50:12.168+0100: 14136.181: Application time: 0.5798363 seconds
{Heap before GC invocations=1724 (full 0):
par new generation total 1887488K, used 1768946K [0x00007fccf1600000,
0x00007fcd71600000, 0x00007fcd71600000)
eden space 1677824K, 100% used [0x00007fccf1600000, 0x00007fcd57c80000,
0x00007fcd57c80000)
from space 209664K, 43% used [0x00007fcd57c80000, 0x00007fcd5d57ca70,
0x00007fcd64940000)
to space 209664K, 0% used [0x00007fcd64940000, 0x00007fcd64940000,
0x00007fcd71600000)
concurrent mark-sweep generation total 34973696K, used 7321858K
[0x00007fcd71600000, 0x00007fd5c8000000, 0x00007fd5c8000000)
Metaspace used 121299K, capacity 134343K, committed 134400K,
reserved 135168K
2017-01-26T12:50:12.170+0100: 14136.182: [GC (Allocation Failure)
2017-01-26T12:50:12.170+0100: 14136.182: [ParNew
Desired survivor size 107347968 bytes, new threshold 6 (max 6)
- age 1: 10383048 bytes, 10383048 total
- age 2: 5102856 bytes, 15485904 total
- age 3: 5154816 bytes, 20640720 total
- age 4: 5080000 bytes, 25720720 total
*- age 5: 37637680 bytes, 63358400 total*
- age 6: 4658912 bytes, 68017312 total
: 1768946K->86544K(1887488K), 0.0929344 secs]
9090805K->7411133K(36861184K), 0.0932244 secs] [Times: user=0.70 sys=0.00,
real=0.09 secs]
Heap after GC invocations=1725 (full 0):
par new generation total 1887488K, used 86544K [0x00007fccf1600000,
0x00007fcd71600000, 0x00007fcd71600000)
eden space 1677824K, 0% used [0x00007fccf1600000, 0x00007fccf1600000,
0x00007fcd57c80000)
from space 209664K, 41% used [0x00007fcd64940000, 0x00007fcd69dc41d0,
0x00007fcd71600000)
to space 209664K, 0% used [0x00007fcd57c80000, 0x00007fcd57c80000,
0x00007fcd64940000)
concurrent mark-sweep generation total 34973696K, used 7324589K
[0x00007fcd71600000, 0x00007fd5c8000000, 0x00007fd5c8000000)
Metaspace used 121299K, capacity 134343K, committed 134400K,
reserved 135168K
}
2017-01-26T12:50:12.263+0100: 14136.276: Total time for which application
threads were stopped: 0.0945634 seconds, Stopping threads took: 0.0001968
seconds
2017-01-26T12:50:12.960+0100: 14136.972: Application time: 0.6966358 seconds
{Heap before GC invocations=1725 (full 0):
par new generation total 1887488K, used 1764368K [0x00007fccf1600000,
0x00007fcd71600000, 0x00007fcd71600000)
eden space 1677824K, 100% used [0x00007fccf1600000, 0x00007fcd57c80000,
0x00007fcd57c80000)
from space 209664K, 41% used [0x00007fcd64940000, 0x00007fcd69dc41d0,
0x00007fcd71600000)
to space 209664K, 0% used [0x00007fcd57c80000, 0x00007fcd57c80000,
0x00007fcd64940000)
concurrent mark-sweep generation total 34973696K, used 7324589K
[0x00007fcd71600000, 0x00007fd5c8000000, 0x00007fd5c8000000)
Metaspace used 121324K, capacity 134471K, committed 134656K,
reserved 135168K
2017-01-26T12:50:12.961+0100: 14136.973: [GC (Allocation Failure)
2017-01-26T12:50:12.961+0100: 14136.973: [ParNew
Desired survivor size 107347968 bytes, new threshold 6 (max 6)
- age 1: 8033264 bytes, 8033264 total
- age 2: 5686168 bytes, 13719432 total
- age 3: 5019640 bytes, 18739072 total
- age 4: 5150920 bytes, 23889992 total
- age 5: 5076720 bytes, 28966712 total
*- age 6: 37481736 bytes, 66448448 total*
: 1764368K->79984K(1887488K), 0.0955902 secs]
9088957K->7407366K(36861184K), 0.0958643 secs] [Times: user=0.69 sys=0.00,
real=0.10 secs]
Heap after GC invocations=1726 (full 0):
par new generation total 1887488K, used 79984K [0x00007fccf1600000,
0x00007fcd71600000, 0x00007fcd71600000)
eden space 1677824K, 0% used [0x00007fccf1600000, 0x00007fccf1600000,
0x00007fcd57c80000)
from space 209664K, 38% used [0x00007fcd57c80000, 0x00007fcd5ca9c148,
0x00007fcd64940000)
to space 209664K, 0% used [0x00007fcd64940000, 0x00007fcd64940000,
0x00007fcd71600000)
concurrent mark-sweep generation total 34973696K, used 7327382K
[0x00007fcd71600000, 0x00007fd5c8000000, 0x00007fd5c8000000)
Metaspace used 121324K, capacity 134471K, committed 134656K,
reserved 135168K
}
2017-01-26T12:50:13.057+0100: 14137.069: Total time for which application
threads were stopped: 0.0972200 seconds, Stopping threads took: 0.0001917
seconds
2017-01-26T12:50:13.683+0100: 14137.695: Application time: 0.6259722 seconds
{Heap before GC invocations=1726 (full 0):
par new generation total 1887488K, used 1757808K [0x00007fccf1600000,
0x00007fcd71600000, 0x00007fcd71600000)
eden space 1677824K, 100% used [0x00007fccf1600000, 0x00007fcd57c80000,
0x00007fcd57c80000)
from space 209664K, 38% used [0x00007fcd57c80000, 0x00007fcd5ca9c148,
0x00007fcd64940000)
to space 209664K, 0% used [0x00007fcd64940000, 0x00007fcd64940000,
0x00007fcd71600000)
concurrent mark-sweep generation total 34973696K, used 7327382K
[0x00007fcd71600000, 0x00007fd5c8000000, 0x00007fd5c8000000)
Metaspace used 121324K, capacity 134471K, committed 134656K,
reserved 135168K
*2017-01-26T12:50:13.684+0100: 14137.697: [GC (Allocation Failure)
2017-01-26T12:50:13.684+0100: 14137.697: [ParNew*
*Desired survivor size 107347968 bytes, new threshold 6 (max 6)*
*- age 1: 10784424 bytes, 10784424 total*
*- age 2: 5148032 bytes, 15932456 total*
*- age 3: 5607232 bytes, 21539688 total*
*- age 4: 5013024 bytes, 26552712 total*
*- age 5: 5148840 bytes, 31701552 total*
*- age 6: 4839808 bytes, 36541360 total*
*: 1757808K->58357K(1887488K), 7.4626505 secs]
9085190K->7420330K(36861184K), 7.4629090 secs] [Times: user=58.63 sys=0.00,
real=7.47 secs] *
Heap after GC invocations=1727 (full 0):
par new generation total 1887488K, used 58357K [0x00007fccf1600000,
0x00007fcd71600000, 0x00007fcd71600000)
eden space 1677824K, 0% used [0x00007fccf1600000, 0x00007fccf1600000,
0x00007fcd57c80000)
from space 209664K, 27% used [0x00007fcd64940000, 0x00007fcd6823d650,
0x00007fcd71600000)
to space 209664K, 0% used [0x00007fcd57c80000, 0x00007fcd57c80000,
0x00007fcd64940000)
concurrent mark-sweep generation total 34973696K, used 7361973K
[0x00007fcd71600000, 0x00007fd5c8000000, 0x00007fd5c8000000)
Metaspace used 121324K, capacity 134471K, committed 134656K,
reserved 135168K
}
*2017-01-26T12:50:21.147+0100: 14145.160: Total time for which application
threads were stopped: 7.4642882 seconds, Stopping threads took: 0.0002572
seconds*
Java HotSpot(TM) 64-Bit Server VM (25.112-b15) for linux-amd64 JRE
(1.8.0_112-b15), built on Sep 22 2016 21:10:53 by "java_re" with gcc 4.3.0
20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 49427048k(42773024k free), swap 4194300k(4194300k
free)
-XX:+AlwaysPreTouch
-XX:+CMSEdenChunksRecordAlways
-XX:CMSInitiatingOccupancyFraction=80
-XX:+CMSParallelInitialMarkEnabled
-XX:+CMSScavengeBeforeRemark
-XX:CMSWaitDuration=60000
-XX:+DisableExplicitGC
-XX:GCLogFileSize=31457280
-XX:InitialHeapSize=37959499776
-XX:MaxHeapSize=37959499776
-XX:MaxMetaspaceSize=268435456
-XX:MaxNewSize=2147483648
-XX:MaxTenuringThreshold=6
-XX:MetaspaceSize=268435456
-XX:NewSize=2147483648
-XX:+UseBiasedLocking
-XX:+UseCMSInitiatingOccupancyOnly
-XX:-UseCompressedOops
-XX:+UseConcMarkSweepGC
-XX:+UseGCLogFileRotation
-XX:+UseLargePages
-XX:+UseParNewGC
Best Regards,
Gustav Åkesson
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20170201/88149404/attachment.html>
More information about the hotspot-gc-use
mailing list