JVM taking a few seconds to reach a safepoint for routine young gen GC

[Vitaly Davidovich]

Jason,

How many java threads are active when these stalls happen? How many CPUs
are available to the jvm? How much physical memory on the machine? Is your
jvm sole occupant of the machine or do you have noisy neighbors? You
mentioned JNI - do you have a lot of JNI calls around these times? Do you
allocate and/or write to large arrays/memory regions? Is there something
different/interesting about these 20 min periods (e.g. workload increases,
same time of day, more disk activity, any paging/swap activity, etc).

sent from my phone
On May 28, 2015 1:58 PM, "Jason Goetz" <jason.goetz at gmail.com> wrote:

> We're consistently seeing a situation where threads take a few seconds to
> stop for a routine GC. For 20 straight minutes the GC will run right away
> (it runs about every second). But then, during a 20-minute period, the
> threads will take longer to stop for GC. See the GC output below.
>
> 2015-05-28T12:14:51.205-0500: 54796.811: Total time for which application
> threads were stopped: 0.1121233 seconds, Stopping threads took: 0.0000908
> seconds
> 2015-05-28T12:15:00.331-0500: 54805.930: Total time for which application
> threads were stopped: 0.0019384 seconds, Stopping threads took: 0.0001106
> seconds
> 2015-05-28T12:15:06.572-0500: 54812.174: [GC concurrent-mark-end,
> 28.4067370 secs]
> 2015-05-28T12:15:09.786-0500: 54815.395: [GC remark
> 2015-05-28T12:15:09.786-0500: 54815.396: [GC ref-proc, 0.0103603 secs],
> 0.0709271 secs]
>  [Times: user=0.73 sys=0.00, real=0.08 secs]
> *2015-05-28T12:15:09.864-0500: 54815.466: Total time for which application
> threads were stopped: 3.2916224 seconds, Stopping threads took: 3.2188032
> seconds*
> 2015-05-28T12:15:09.864-0500: 54815.467: [GC cleanup 20G->20G(30G),
> 0.0451098 secs]
>  [Times: user=0.61 sys=0.00, real=0.05 secs]
> 2015-05-28T12:15:09.910-0500: 54815.512: Total time for which application
> threads were stopped: 0.0459803 seconds, Stopping threads took: 0.0001950
> seconds
>
> Turning on safepoint logging reveals that these stopping threads times are
> taken up by safepoint ‘sync’ time. Taking thread dumps every second around
> these pauses fail to show anything of note happening during this time, but
> it’s my understanding that native code won’t necessarily show up in thread
> dumps anyway given that they exit before the JVM reaches a safepoint.
>
> Enabling PrintJNIGCStalls fails to show any logging around the 3 second
> pause seen above. I highly suspected JNI but was surprise that I didn’t see
> any logging about JNI Weak References after turning that option on. Any
> ideas for what I can try next? We’re using JDK 7u80. Here are the rest of
> my JVM settings:
>
> DisableExplicitGC true
> FlightRecorder true
> GCLogFileSize 52428800
> ManagementServer true
> MinHeapSize 25769803776
> MaxHeapSize 25769803776
> MaxPermSize 536870912
> NumberOfGCLogFiles 10
> PrintAdaptiveSizePolicy true
> PrintGC true
> PrintGCApplicationStoppedTime true
> PrintGCCause true
> PrintGCDateStamps true
> PrintGCDetails true
> PrintGCTimeStamps true
> PrintSafepointStatistics true
> PrintSafepointStatisticsCount 1
> PrintTenuringDistribution true
> ReservedCodeCacheSize 268435456
> SafepointTimeout true
> SafepointTimeoutDelay 4000
> ThreadStackSize 4096
> UnlockCommercialFeatures true
> UseBiasedLocking false
> UseGCLogFileRotation false
> UseG1GC true
> PrintJNIGCStalls true
>
>
>
> _______________________________________________
> 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/20150528/cfe77e44/attachment.html>