4
我看到GC日誌中看起來與垃圾收集無關的應用程序暫停時間非常長。該應用程序位於16GB堆上，分配的內存吞吐量相當大。我知道GC日誌會顯示與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暫停顯示爲同步時間。我將不得不閱讀更多關於這意味着什麼。
你如何衡量「應用程序線程被停止的總時間」？或者是GC輸出的那部分？ – Sbodd
只需使用[*此技術*]（http://stackoverflow.com/a/317160/23771）。有些線程會做某些事情，它會告訴你什麼。如果它在GC中停止，那不會告訴你很多，但GC'd的所有內容也必須是'new'ed，所以如果你用'new'（在多個樣本中）捕獲它，值得儘量避免這樣做。 –
停止應用程序線程的總時間來自選項「PrintGCApplicationStoppedTime」 – jgoetz