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

[Jason Goetz]

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




-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20150528/462b6d22/attachment.html>