爲什麼我遇到很長的與GC無關的應用程序暫停？

Question

我看到GC日誌中看起來與垃圾收集無關的應用程序暫停時間非常長。該應用程序位於16GB堆上，分配的內存吞吐量相當大。我知道GC日誌會顯示與GC不一定相關的暫停，這似乎就是這種情況。

另外，這些暫停的CPU達到100％時，不存在磁盤或存儲器I/O，並且沒有記錄活動（由於停止所有應用程序線程）。

什麼可能導致這些長期停頓，或是如何追蹤根源下來有什麼建議任何想法？

下面是從日誌中的相關片段（注意151秒暫停）：

2015-04-21T06:30:04.834-0500: 217179.483: [GC (Allocation Failure)2015-04-21T06:30:04.849-0500: 217179.483: [ParNew 
Desired survivor size 43614208 bytes, new threshold 6 (max 6) 
- age 1: 19876896 bytes, 19876896 total 
- age 2: 15903904 bytes, 35780800 total 
- age 3:  617120 bytes, 36397920 total 
- age 4:  34096 bytes, 36432016 total 
- age 5:  399896 bytes, 36831912 total 
- age 6:  71112 bytes, 36903024 total 
: 706301K->45145K(766784K), 0.0681632 secs] 19029029K->18368371K(25080640K), 0.0684183 secs] [Times: user=0.44 sys=0.00, real=0.08 secs] 
2015-04-21T06:30:05.816-0500: 217180.453: Total time for which application threads were stopped: 1.8507910 seconds 
2015-04-21T06:30:09.171-0500: 217183.812: [GC (Allocation Failure)2015-04-21T06:30:09.171-0500: 217183.812: [ParNew 
Desired survivor size 43614208 bytes, new threshold 6 (max 6) 
- age 1: 14812976 bytes, 14812976 total 
- age 2: 3411968 bytes, 18224944 total 
- age 3: 14952032 bytes, 33176976 total 
- age 4:  430048 bytes, 33607024 total 
- age 5:  32864 bytes, 33639888 total 
- age 6:  374880 bytes, 34014768 total 
: 726745K->43352K(766784K), 0.0673428 secs] 19049971K->18366645K(25080640K), 0.0675792 secs] [Times: user=0.48 sys=0.00, real=0.06 secs] 
2015-04-21T06:30:09.249-0500: 217183.886: Total time for which application threads were stopped: 0.0763406 seconds 
2015-04-21T06:32:43.960-0500: 217338.603: Total time for which application threads were stopped: 151.1866188 seconds 
2015-04-21T06:32:43.975-0500: 217338.607: [GC (GCLocker Initiated GC)2015-04-21T06:32:43.975-0500: 217338.607: [ParNew 
Desired survivor size 43614208 bytes, new threshold 4 (max 6) 
- age 1: 18173880 bytes, 18173880 total 
- age 2: 9659800 bytes, 27833680 total 
- age 3: 3400176 bytes, 31233856 total 
- age 4: 14928944 bytes, 46162800 total 
- age 5:  375056 bytes, 46537856 total 
- age 6:  31880 bytes, 46569736 total 
: 727682K->56678K(766784K), 0.0759093 secs] 19050975K->18380341K(25080640K), 0.0760795 secs] [Times: user=0.58 sys=0.00, real=0.08 secs] 
2015-04-21T06:32:44.053-0500: 217338.684: Total time for which application threads were stopped: 0.0769955 seconds 

這裏是我的JVM設置的時刻：

-Xmx16g 
-XX:MaxPermSize=256m 
-Dcom.sun.management.jmxremote 
-Dcom.sun.management.jmxremote.authenticate=true 
-Dcom.sun.management.jmxremote.login.config=JmxFileLoginModule 
-Dcom.sun.management.jmxremote.port=8082 
-Dcom.sun.management.jmxremote.ssl=false 
-Dfile.encoding=UTF8 
-Djava.awt.headless=true 
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager 
-Xloggc:{fileLoc} 
-XX:+DisableExplicitGC 
-XX:+PrintAdaptiveSizePolicy 
-XX:+PrintGCApplicationStoppedTime 
-XX:+PrintGCCause 
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails 
-XX:+PrintTenuringDistribution 
-XX:+UseConcMarkSweepGC 
-XX:+UseParNewGC 
-XX:GCLogFileSize=50M 
-XX:NumberOfGCLogFiles=10 
-XX:ReservedCodeCacheSize=256M 
-XX:-UseGCLogFileRotation 
-XX:+PrintSafepointStatistics 
-XX:+SafepointTimeout 
-XX:SafepointTimeoutDelay=4000 
-XX:+PrintSafepointStatistics 

UPDATE：

我忘記在這裏包含我的安全點記錄。這是我的還原點日誌是什麼樣子了151秒的停頓以上經歷：

217338.603: [sweeping nmethods, 0.0000036 secs] 
      vmop     [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count 
    217187.422: GenCollectForAllocation   [  140   46    1 ]  [  1  0151184  2  0 ] 0 

塊時間爲0，但它似乎對旁邊的同步時間，所以同步時間實際上是151184.

對於其他的GC相關的暫停還原點日誌中會出現這樣的：

107100.562: [sweeping nmethods, 0.0000015 secs] 
     vmop     [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count 
107100.563: GenCollectForAllocation   [  117   0    0 ]  [  0  0  0  0 38238 ] 0 

因此，GC暫停顯示爲vmop時間和非GC暫停顯示爲同步時間。我將不得不閱讀更多關於這意味着什麼。

Answer 1

我們遇到了類似的問題，這似乎是一個JVM錯誤JDK-8041984。
我不知道這是你的情況爲好，但考慮更新到JDK 8u45或7u80。

只要看到這個問題再次嘗試採取這種長時間的停頓期間與本地幀強制堆棧轉儲：

jstack -F -m <PID> 

這將有助於確定哪些虛擬機正在做，即使過程中沒有響應。

Answer 2

塊時間爲0，但它似乎對旁邊的同步時間，所以同步時間實際上是151184.

您正在閱讀的輸出錯誤，由於標籤上的標題是沒有正確對齊，您需要對列進行計數。

據我所知，它基本上在等待151秒達到一個還原點，因爲增變線程仍然是一個活儘管還原點陷阱活躍。

當它在本機代碼中花費太多時間或者@apangin提到編譯器線程做了大量工作時，可能會發生這種情況。

我認爲還有一些情況是編譯器會在循環backedge中優化掉一個安全點，當它可以證明循環在有限的時間內完成時，循環遍歷長計數器可能需要幾秒鐘的時間。