Question regarding one off long GC pause times.
Kirti Teja Rao
kirtiteja at gmail.com
Fri Aug 28 17:33:10 UTC 2015
Hi Carlo,
In addition to what Ramki said, you may want to set vm.swappiness to 0
(Default is 60 on most linux systems).
Also, if there is high IO load, gc logging can also impact pause times
(logging happens inside the pause time).
Thanks,
Teja
On Fri, Aug 28, 2015 at 9:00 AM, Srinivas Ramakrishna <ysr1729 at gmail.com>
wrote:
> 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
>>
>>
>
> _______________________________________________
> 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/c2015d16/attachment.html>
More information about the hotspot-gc-use
mailing list