Question regarding one off long GC pause times.

[Fernando, Carlo]

Hi.

I have been seeing long ( > 1sec) GC pauses in our latency sensitive application. I have enabled SafepointStatistics thinking that there was something else that could have been causing this but based on the output, it seems like everything is humming along nicely with GC taking only ~1ms then this >1 sec GC happens all of a sudden. I was wondering if anybody had observed similar behavior and has some explanation why this is happening.

I have attached my flags and a snippet of my GC. Any info I appreciated.

JAVA 7 FLAGS:
-Xms256M -Xmx256M -XX:NewSize=146M -XX:TargetSurvivorRatio=90 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:ParallelGCThreads=8 -XX:+DisableExplicitGC -XX:CMSInitiatingOccupancyFraction=50 -XX:SurvivorRatio=160 -XX:MaxTenuringThreshold=1 -XX:+UseStringCache -XX:+UseCompressedStrings -XX:+OptimizeStringConcat -XX:+AggressiveOpts -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintSafepointStatistics -XX:+PerfDisableSharedMem


SAFEPOINT:
55638.934: GenCollectForAllocation          [     174          0              0    ]      [     0     0     0     0     1    ]  0
55643.367: GenCollectForAllocation          [     174          0              1    ]      [     0     0     0     0     1    ]  0
55647.391: GenCollectForAllocation          [     174          1              0    ]      [     0     0     0     0     1    ]  0
55650.766: GenCollectForAllocation          [     174          0              0    ]      [     0     0     0     0  1538    ]  0
55654.785: GenCollectForAllocation          [     174          0              0    ]      [     0     0     0     0     1    ]  0
55661.227: GenCollectForAllocation          [     174          0              0    ]      [     0     0     0     0     1    ]  0


GC:
2015-08-28T08:29:44.486-0400: 55643.368: [GC 55643.368: [ParNew: 147851K->118K(148608K), 0.0014580 secs] 171468K->23745K(261248K), 0.0015420 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
Total time for which application threads were stopped: 0.0018720 seconds
Application time: 4.0202340 seconds
2015-08-28T08:29:48.508-0400: 55647.390: [GC 55647.391: [ParNew: 147830K->225K(148608K), 0.0011710 secs] 171457K->23852K(261248K), 0.0012660 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Total time for which application threads were stopped: 0.0016180 seconds
Application time: 3.3738970 seconds
2015-08-28T08:29:51.883-0400: 55650.766: [GC 55652.303: [ParNew: 147937K->247K(148608K), 0.0009800 secs] 171564K->23955K(261248K), 0.0010800 secs] [Times: user=0.01 sys=0.00, real=1.54 secs]
Total time for which application threads were stopped: 1.5383140 seconds
Application time: 2.4803280 seconds
2015-08-28T08:29:55.902-0400: 55654.785: [GC 55654.785: [ParNew: 147959K->137K(148608K), 0.0009230 secs] 171667K->23853K(261248K), 0.0009900 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
Total time for which application threads were stopped: 0.0012740 seconds
Application time: 6.4405350 seconds
2015-08-28T08:30:02.344-0400: 55661.226: [GC 55661.226: [ParNew: 147849K->156K(148608K), 0.0008740 secs] 171565K->23877K(261248K), 0.0009480 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
Total time for which application threads were stopped: 0.0012230 seconds
Application time: 5.1378200 seconds

----------------------------------------------------------------------
This message, and any attachments, is for the intended recipient(s) only, may contain information that is privileged, confidential and/or proprietary and subject to important terms and conditions available at http://www.bankofamerica.com/emaildisclaimer.   If you are not the intended recipient, please delete this message.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20150828/da510aeb/attachment.html>