Question regarding one off long GC pause times.

charlie hunt charlie.hunt at oracle.com
Fri Aug 28 19:36:40 UTC 2015


While you have your sys admin handy, also have him check that 
transparent huge pages are disabled.

charlie

On 08/28/2015 02:06 PM, Fernando, Carlo wrote:
>
> Hi.
>
> I will loop in our Sys admin and we will try a test with this setting.
>
> Appreciate the response.
>
> Thanks
>
> -carlo
>
> *From:*Kirti Teja Rao [mailto:kirtiteja at gmail.com]
> *Sent:* Friday, August 28, 2015 12:33 PM
> *To:* Srinivas Ramakrishna
> *Cc:* Fernando, Carlo; hotspot-gc-use at openjdk.java.net
> *Subject:* Re: Question regarding one off long GC pause times.
>
> 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 <mailto: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 <mailto: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
>     <mailto: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 <mailto:hotspot-gc-use at openjdk.java.net>
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
> ------------------------------------------------------------------------
> 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/b95c8b47/attachment-0001.html>


More information about the hotspot-gc-use mailing list