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

[Poonam Bajaj Parhar]

Hello Jason,

On 5/28/2015 10:58 AM, Jason Goetz 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.
>
Could you please share the output collected with 
PrintSafepointStatisticsoption. That may tell us which VM-operation is 
having trouble in stopping threads before starting the actual work.

> Enabling PrintJNIGCStalls fails to show any logging around the 3 
> second pause seen above.

PrintJNIGCStalls option logs the events when a GC invocation request is 
made by any of the application threads but GC can not be invoked at that 
time because one or more of the applications threads are running in a 
JNI Critical Section. So, the GC is stalled until threads come out of 
the JNI critical section, and as threads exit the JNI critical section 
GC request is honored.

If this option didn't print anything that means that the application 
didn't encounter any such situation.

Thanks,
Poonam

> 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:
>
> DisableExplicitGCtrue
> FlightRecordertrue
> GCLogFileSize52428800
> ManagementServertrue
> MinHeapSize25769803776
> MaxHeapSize25769803776
> MaxPermSize536870912
> NumberOfGCLogFiles10
> PrintAdaptiveSizePolicytrue
> PrintGCtrue
> PrintGCApplicationStoppedTimetrue
> PrintGCCausetrue
> PrintGCDateStampstrue
> PrintGCDetailstrue
> PrintGCTimeStampstrue
> PrintSafepointStatisticstrue
> PrintSafepointStatisticsCount1
> PrintTenuringDistributiontrue
> ReservedCodeCacheSize268435456
> SafepointTimeouttrue
> SafepointTimeoutDelay4000
> ThreadStackSize4096
> UnlockCommercialFeaturestrue
> UseBiasedLockingfalse
> UseGCLogFileRotationfalse
> UseG1GCtrue
> PrintJNIGCStallstrue
>
>
>
>
> _______________________________________________
> 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/c9822f11/attachment-0001.html>