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

[Krishnamurthy, Kannan]

Thanks for the responses. I agree with Jenny that the gc logs doesn't seem to indicate that the pause was from a GC event.

Profiling the application and trying to get some native stack traces/ core dumps.
________________________________
From: Martin Makundi [martin.makundi at koodaripalvelut.com]
Sent: Monday, August 25, 2014 10:07 PM
To: Yu Zhang
Cc: Krishnamurthy, Kannan; hotspot-gc-use at openjdk.java.net; kndkannan at gmail.com
Subject: Re: Unexplained long stop the world pauses during concurrent marking step in G1 Collector

Try running command kill -3 <pid> to see what's going on with the application threads.

**
Martin


2014-08-26 4:48 GMT+03:00 Yu Zhang <yu.zhang at oracle.com<mailto:yu.zhang at oracle.com>>:
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<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


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