Question regarding one off long GC pause times.

[Srinivas Ramakrishna]

Hi Carlo --

Two possible avenues worth investigating:

(1) check if there's any kind of periodicity to such events. If that is the
case, see if there's something else that runs periodically on the same
machine (note that only the elapsed time is affected here, as if for some
reason the process was stalled for that amount of time; GC itself seems
to finish quite quickly, by the way.)

(2) There was a recent thread from Evan Jones on how, if your /tmp is not a
tmpfs partition (but rather a disk-based partition) then, in the presence
of high I/O load, there can be situations (particularly with the Linux
virtual memory manager) where the perfdata pages can be occasionally
evicted to disk. When the JVM tries to update the perfdata counters at the
end of GC, we end up taking page misses that can impact pause times. A
suggested workaround was to use: -XX:-UsePerfData to stop such perfdata
segment logging (you will lose access to those counters externally of
course), and avoid that pause time hit.

There can be other possibilities as well, but given the symptom here, of
only the elapsed time being affected, chances are that one of these (and
possibly (1)) is a likely cause.

Good luck!
-- ramki


On Fri, Aug 28, 2015 at 7:21 AM, Fernando, Carlo <carlo.fernando at baml.com>
wrote:

>
>
> 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.
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20150828/748c86e3/attachment-0001.html>