ParNew latency
Gustav Åkesson
gustav.r.akesson at gmail.com
Wed Dec 26 18:14:56 UTC 2018
Hello folks,
I have noticed a peculiar behaviour with CMS and ParNew, in which the
latency of ParNew is significantly higher before the first CMS cycle has
occurred. Looking at the GC logs further down in this mail, we see it drops
from around 45ms down to around 35ms. This observation is consistent and
reproducible every time.
>From what I can tell, it seems to be some type of internal CMS ergonomics
that is adjusted after first CMS cycle that improves the ParNew STW latency.
Any thoughts on this?
What could this be and is there any non-default flag that can be set to get
the "post CMS cycle" latency right from start?
-----------------------
*Set JVM flags and platform*
Java HotSpot(TM) 64-Bit Server VM (25.181-b25) for linux-amd64 JRE
(1.8.0_181-b25), built on Jun 29 2018 00:52:17 by "java_re" with gcc 4.3.0
20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 41037916k(35541784k free), swap 4194300k(4132448k
free)
CommandLine flags: -XX:+AlwaysPreTouch -XX:+CMSEdenChunksRecordAlways
-XX:CMSInitiatingOccupancyFraction=80 -XX:+CMSParallelInitialMarkEnabled
-XX:+CMSScavengeBeforeRemark -XX:CMSWaitDuration=60000
-XX:CompressedClassSpaceSize=33554432 -XX:+DebugNonSafepoints
-XX:+DisableExplicitGC -XX:ErrorFile=**** -XX:+FlightRecorder
-XX:GCLogFileSize=31457280 -XX:InitialHeapSize=31517048832
-XX:MaxHeapSize=31517048832 -XX:MaxMetaspaceSize=268435456
-XX:MaxNewSize=2147483648 -XX:MaxTenuringThreshold=6
-XX:MetaspaceSize=268435456 -XX:NewSize=2147483648 -XX:NumberOfGCLogFiles=3
-XX:OldPLABSize=16 -XX:+PreserveFramePointer -XX:+PrintGC
-XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-XX:+PrintTenuringDistribution -XX:ReservedCodeCacheSize=134217728
-XX:+TieredCompilation -XX:+UnlockCommercialFeatures
-XX:+UnlockDiagnosticVMOptions -XX:+UseBiasedLocking
-XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers
-XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseGCLogFileRotation
-XX:+UseParNewGC
*GC logs*
2018-12-11T13:23:28.667+0100: 80955.318: [GC (Allocation Failure)
2018-12-11T13:23:28.667+0100: 80955.318: [ParNew
Desired survivor size 107347968 bytes, new threshold 6 (max 6)
- age 1: 6087736 bytes, 6087736 total
- age 2: 4069464 bytes, 10157200 total
- age 3: 3749080 bytes, 13906280 total
- age 4: 3149152 bytes, 17055432 total
- age 5: 2986288 bytes, 20041720 total
- age 6: 2861776 bytes, 22903496 total
: 1707782K->32210K(1887488K), 0.0445715 secs]
24644965K->22972174K(30569728K), 0.0448519 secs] [Times: user=0.33
sys=0.00, real=0.05 secs]
2018-12-11T13:23:29.748+0100: 80956.400: [GC (Allocation Failure)
2018-12-11T13:23:29.748+0100: 80956.400: [ParNew
Desired survivor size 107347968 bytes, new threshold 6 (max 6)
- age 1: 6113256 bytes, 6113256 total
- age 2: 4078992 bytes, 10192248 total
- age 3: 3700760 bytes, 13893008 total
- age 4: 3213552 bytes, 17106560 total
- age 5: 2955112 bytes, 20061672 total
- age 6: 2881016 bytes, 22942688 total
: 1710034K->31117K(1887488K), 0.0446833 secs]
24649998K->22973867K(30569728K), 0.0449682 secs] [Times: user=0.34
sys=0.00, real=0.05 secs]
2018-12-11T13:23:30.830+0100: 80957.482: [GC (Allocation Failure)
2018-12-11T13:23:30.831+0100: 80957.482: [ParNew
Desired survivor size 107347968 bytes, new threshold 6 (max 6)
- age 1: 7805344 bytes, 7805344 total
- age 2: 4043072 bytes, 11848416 total
- age 3: 3742544 bytes, 15590960 total
- age 4: 3180256 bytes, 18771216 total
- age 5: 2986552 bytes, 21757768 total
- age 6: 2871136 bytes, 24628904 total
*: 1708941K->39307K(1887488K), 0.0486555 secs]
24651691K->22984857K(30569728K), 0.0489488 secs] [Times: user=0.34
sys=0.00, real=0.05 secs] *
2018-12-11T13:23:31.918+0100: 80958.570: [GC (Allocation Failure)
2018-12-11T13:23:31.918+0100: 80958.570: [ParNew
Desired survivor size 107347968 bytes, new threshold 6 (max 6)
- age 1: 7905160 bytes, 7905160 total
- age 2: 4058768 bytes, 11963928 total
- age 3: 3702320 bytes, 15666248 total
- age 4: 3218448 bytes, 18884696 total
- age 5: 2965648 bytes, 21850344 total
- age 6: 2868192 bytes, 24718536 total
: 1717131K->38437K(1887488K), 0.0480072 secs]
24662681K->22986764K(30569728K), 0.0483032 secs] [Times: user=0.32
sys=0.00, real=0.05 secs]
*2018-12-11T13:23:31.970+0100: 80958.621: [GC (CMS Initial Mark) [1
CMS-initial-mark: 22948327K(28682240K)] 23010362K(30569728K), 0.0076862
secs] [Times: user=0.03 sys=0.01, real=0.01 secs] *
2018-12-11T13:23:31.978+0100: 80958.630: [CMS-concurrent-mark-start]
2018-12-11T13:23:32.808+0100: 80959.460: [CMS-concurrent-mark: 0.830/0.830
secs] [Times: user=5.07 sys=0.49, real=0.83 secs]
2018-12-11T13:23:32.808+0100: 80959.460: [CMS-concurrent-preclean-start]
2018-12-11T13:23:32.867+0100: 80959.518: [CMS-concurrent-preclean:
0.057/0.058 secs] [Times: user=0.33 sys=0.03, real=0.06 secs]
2018-12-11T13:23:32.867+0100: 80959.518:
[CMS-concurrent-abortable-preclean-start]
2018-12-11T13:23:33.002+0100: 80959.653: [GC (Allocation Failure)
2018-12-11T13:23:33.002+0100: 80959.654: [ParNew
Desired survivor size 107347968 bytes, new threshold 6 (max 6)
- age 1: 6792248 bytes, 6792248 total
- age 2: 4085632 bytes, 10877880 total
- age 3: 3725496 bytes, 14603376 total
- age 4: 3163816 bytes, 17767192 total
- age 5: 2998648 bytes, 20765840 total
- age 6: 2836880 bytes, 23602720 total
: 1716261K->36026K(1887488K), 0.0459681 secs]
24664588K->22987134K(30569728K), 0.0462493 secs] [Times: user=0.33
sys=0.00, real=0.04 secs]
2018-12-11T13:23:33.647+0100: 80960.299:
[CMS-concurrent-abortable-preclean: 0.728/0.780 secs] [Times: user=4.33
sys=0.45, real=0.78 secs]
2018-12-11T13:23:33.649+0100: 80960.300: [GC (CMS Final Remark) [YG
occupancy: 1044991 K (1887488 K)]2018-12-11T13:23:33.649+0100: 80960.301:
[GC (CMS Final Remark) 2018-12-11T13:23:33.649+0100: 80960.301: [ParNew
Desired survivor size 107347968 bytes, new threshold 6 (max 6)
- age 1: 4522096 bytes, 4522096 total
- age 2: 4087288 bytes, 8609384 total
- age 3: 3962800 bytes, 12572184 total
- age 4: 3364480 bytes, 15936664 total
- age 5: 3025768 bytes, 18962432 total
- age 6: 2922328 bytes, 21884760 total
: 1044991K->29113K(1887488K), 0.0456241 secs]
23996098K->22982992K(30569728K), 0.0458796 secs] [Times: user=0.33
sys=0.00, real=0.05 secs]
2018-12-11T13:23:33.695+0100: 80960.346: [Rescan (parallel) , 0.0138960
secs]2018-12-11T13:23:33.709+0100: 80960.360: [weak refs processing,
0.0022424 secs]2018-12-11T13:23:33.711+0100: 80960.363: [class unloading,
0.1338832 secs]2018-12-11T13:23:33.845+0100: 80960.497: [scrub symbol
table, 0.0140718 secs]2018-12-11T13:23:33.859+0100: 80960.511: [scrub
string table, 0.0017299 secs][1 CMS-remark: 22953878K(28682240K)]
22982992K(30569728K), 0.2419581 secs] [Times: user=0.62 sys=0.00, real=0.25
secs]
2018-12-11T13:23:33.891+0100: 80960.543: [CMS-concurrent-sweep-start]
2018-12-11T13:23:34.725+0100: 80961.377: [GC (Allocation Failure)
2018-12-11T13:23:34.725+0100: 80961.377: [ParNew
Desired survivor size 107347968 bytes, new threshold 6 (max 6)
- age 1: 7697232 bytes, 7697232 total
- age 2: 2434936 bytes, 10132168 total
- age 3: 3934840 bytes, 14067008 total
- age 4: 3348704 bytes, 17415712 total
- age 5: 3063832 bytes, 20479544 total
- age 6: 2907808 bytes, 23387352 total
*: 1706937K->35508K(1887488K), 0.0355183 secs]
24048561K->22379955K(30569728K), 0.0358070 secs] [Times: user=0.27
sys=0.00, real=0.04 secs] *
2018-12-11T13:23:35.816+0100: 80962.468: [GC (Allocation Failure)
2018-12-11T13:23:35.816+0100: 80962.468: [ParNew
Desired survivor size 107347968 bytes, new threshold 6 (max 6)
- age 1: 8502816 bytes, 8502816 total
- age 2: 4081456 bytes, 12584272 total
- age 3: 2307088 bytes, 14891360 total
- age 4: 3364944 bytes, 18256304 total
- age 5: 3066568 bytes, 21322872 total
- age 6: 2913112 bytes, 24235984 total
: 1713332K->36712K(1887488K), 0.0401425 secs]
23188060K->21514239K(30569728K), 0.0404617 secs] [Times: user=0.29
sys=0.00, real=0.04 secs]
2018-12-11T13:23:36.892+0100: 80963.543: [GC (Allocation Failure)
2018-12-11T13:23:36.892+0100: 80963.543: [ParNew
Desired survivor size 107347968 bytes, new threshold 6 (max 6)
- age 1: 7042632 bytes, 7042632 total
- age 2: 4060640 bytes, 11103272 total
- age 3: 3764904 bytes, 14868176 total
- age 4: 1924712 bytes, 16792888 total
- age 5: 3078712 bytes, 19871600 total
- age 6: 2911152 bytes, 22782752 total
: 1714536K->32173K(1887488K), 0.0364840 secs]
22227971K->20548418K(30569728K), 0.0367772 secs] [Times: user=0.27
sys=0.00, real=0.03 secs]
-----------------------
Best Regards,
Gustav Åkesson
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20181226/f5f9c281/attachment.html>
More information about the hotspot-gc-use
mailing list