Unexplained long stop the world pauses during concurrent marking step in G1 Collector

[Yu Zhang]

Kannan,

The concurrent marking is concurrent, meaning it runs concurrently with 
the application.
You may see the time between[GC concurrent-mark-start] and
[GC concurrent-mark-stop] very long, maybe even some young gc happened 
during this time period.  This is because the marking threads can be 
suspended.

 >*2014-08-07T13:42:39.598-0400: 92192.348: Application time: 9.0448670 
seconds**
     2014-08-07T13:42:39.601-0400: 92192.351: Total time for which 
application threads were stopped: 0.0029740 seconds
This means the application has run for 9.0448670 seconds.  And only 
being stopped for
0.0029740 seconds.

 From this log, gc did not stop the application.

 >Linux "top" shows single CPU at 100% and rest of the CPUs at 0% during 
the pause.
Maybe something in the application or OS is running on 1 cpu and 
blocking other threads.

Thanks,
Jenny

On 8/18/2014 1:34 PM, Krishnamurthy, Kannan wrote:
> Greetings,
>
> We are experiencing unexplained/unknown long pauses (8 seconds) during 
> concurrent marking step of G1 collector.
>
>     2014-08-07T13:42:30.552-0400: 92183.303: [GC 
> concurrent-root-region-scan-start]
>     2014-08-07T13:42:30.555-0400: 92183.305: [GC 
> concurrent-root-region-scan-end, 0.0025230 secs]
>     **2014-08-07T13:42:30.555-0400: 92183.305: [GC 
> concurrent-mark-start]**
>     **2014-08-07T13:42:39.598-0400: 92192.348: Application time: 
> 9.0448670 seconds**
>     2014-08-07T13:42:39.601-0400: 92192.351: Total time for which 
> application threads were stopped: 0.0029740 seconds
>     2014-08-07T13:42:39.603-0400: 92192.353: [GC pause (G1 Evacuation 
> Pause) (young) 92192.354: [G1Ergonomics (CSet Construction) start 
> choosing CSet, _pending_cards: 7980, predicted base time: 28.19 ms, 
> remaining time: 71.81 ms, target pause time: 100.00 ms
>
>
> `2014-08-07T13:42:30.555-0400: 92183.305` is when the concurrent mark 
> starts, approximately after 2 seconds of this step the application 
> starts to pause. However the GC logs claims the application was not 
> paused during this window.
> Linux "top" shows single CPU at 100% and rest of the CPUs at 0% during 
> the pause.
>
> Any help in understanding the root cause of this issue is appreciated.
>
> Our target JVMS:
>
>     java version "1.7.0_04"
>     Java(TM) SE Runtime Environment (build 1.7.0_04-b20)
>     Java HotSpot(TM) 64-Bit Server VM (build 23.0-b21, mixed mode)
>
>     java version "1.8.0_11"
>     Java(TM) SE Runtime Environment (build 1.8.0_11-b12)
>     Java HotSpot(TM) 64-Bit Server VM (build 25.11-b03, mixed mode)
>
>
> Our JVM options :
>
>     -Xms20G -Xmx20G -Xss10M -XX:PermSize=128M -XX:MaxPermSize=128M 
> -XX:MarkStackSize=16M
>     -XX:+UnlockDiagnosticVMOptions -XX:+G1PrintRegionLivenessInfo 
> -XX:+TraceGCTaskThread
>     -XX:+G1SummarizeConcMark -XX:+G1SummarizeRSetStats 
> -XX:+G1TraceConcRefinement
>     -XX:+UseG1GC -XX:MaxGCPauseMillis=100 
> -XX:InitiatingHeapOccupancyPercent=65
>     -XX:ParallelGCThreads=24 -verbose:gc -XX:+PrintGC -XX:+PrintGCDetails
>     -XX:+PrintGCDateStamps -XX:+PrintAdaptiveSizePolicy 
> -XX:+PrintTenuringDistribution
>     -XX:+PrintGCApplicationStoppedTime 
> -XX:+PrintGCApplicationConcurrentTime
>     -Xloggc:/common/logs/ocean-partition-gc.log
>
>
> Thanks and regards,
> Kannan
>
>
>
> _______________________________________________
> 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/20140825/45577d4d/attachment.html>