完全gc後JVM鎖定

Question

最近我們剛剛注意到我們的許多服務器零星地和突然地（沒有可辨別的逐漸退化）鎖定在下面的堆棧中（所有其他的塊都是BLOCKED，IN_NATIVE或IN_VM）（在我們的代碼處截斷開始），得到使用jstack -F

Thread 18334: (state = IN_JAVA) 
- java.util.Calendar.updateTime() @bci=1, line=2469 (Compiled frame; information may be imprecise) 
- java.util.Calendar.getTimeInMillis() @bci=8, line=1088 (Compiled frame) 
(truncated) 

失敗似乎滿GC後不久發生，並且頂部-H -p顯示有兩個線程，一個似乎是上述螺紋，另是一個gc線程或一個jitc，根據pstack（不是VMThread :: run（））的以下輸出：

Thread 331 (Thread 0x7f59641bc700 (LWP 16461)): 
#0 0x00007f63f9ed0ef8 in SafepointSynchronize::begin()() from /usr/java/jdk1.6.0_33/jre/lib/amd64/server/libjvm.so 
#1 0x00007f63f9fbab7c in VMThread::loop()() from /usr/java/jdk1.6.0_33/jre/lib/amd64/server/libjvm.so 
#2 0x00007f63f9fba68e in VMThread::run()() from /usr/java/jdk1.6.0_33/jre/lib/amd64/server/libjvm.so 
#3 0x00007f63f9e5e7af in java_start(Thread*)() from /usr/java/jdk1.6.0_33/jre/lib/amd64/server/libjvm.so 
#4 0x00000035bb807851 in start_thread() from /lib64/libpthread.so.0 
#5 0x00000035bb4e811d in clone() from /lib64/libc.so.6 

有沒有人有任何想法，爲什麼這可能已經開始發生？

我們在24核心（12物理）的服務器上使用CentOS 5.7和6.3版上的jdk1.6.0_33。

這裏有一些更棧，與我們的代碼截斷：

Thread 22561: (state = IN_VM) 
- java.lang.String.toLowerCase(java.util.Locale) @bci=428, line=2782 (Compiled frame; information may be imprecise) 
- java.lang.String.toLowerCase() @bci=4, line=2847 (Compiled frame) 
(truncated) 

Thread 22562: (state = IN_VM) 
- java.util.HashMap.put(java.lang.Object, java.lang.Object) @bci=20, line=403 (Compiled frame; information may be imprecise) 
- java.util.HashSet.add(java.lang.Object) @bci=8, line=200 (Compiled frame) 
(truncated) 

Thread 22558: (state = BLOCKED) 
- sun.nio.ch.EPollSelectorImpl.wakeup() @bci=6, line=173 (Compiled frame) 
- org.mortbay.io.nio.SelectorManager$SelectSet.wakeup() @bci=10, line=706 (Compiled frame) 
- org.mortbay.io.nio.SelectChannelEndPoint.updateKey() @bci=135, line=344 (Compiled frame) 
- org.mortbay.io.nio.SelectChannelEndPoint.undispatch() @bci=10, line=204 (Compiled frame) 
- org.mortbay.jetty.nio.SelectChannelConnector$ConnectorEndPoint.undispatch() @bci=54, line=382 (Compiled frame) 
- org.mortbay.io.nio.SelectChannelEndPoint.run() @bci=44, line=449 (Compiled frame) 
- org.mortbay.thread.QueuedThreadPool$PoolThread.run() @bci=25, line=534 (Compiled frame) 

Thread 22557: (state = BLOCKED) 
- java.lang.Object.wait(long) @bci=0 (Compiled frame; information may be imprecise) 
- java.lang.Object.wait(long, int) @bci=58, line=443 (Compiled frame) 
- com.stumbleupon.async.Deferred.doJoin(boolean, long) @bci=244, line=1148 (Compiled frame) 
- com.stumbleupon.async.Deferred.join(long) @bci=3, line=1028 (Compiled frame) 
(truncated) 

Thread 20907: (state = IN_NATIVE) 
- java.net.PlainSocketImpl.socketAccept(java.net.SocketImpl) @bci=0 (Interpreted frame) 
- java.net.PlainSocketImpl.accept(java.net.SocketImpl) @bci=7, line=408 (Interpreted frame) 
- java.net.ServerSocket.implAccept(java.net.Socket) @bci=60, line=462 (Interpreted frame) 
- java.net.ServerSocket.accept() @bci=48, line=430 (Interpreted frame) 
- sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop() @bci=55, line=369 (Interpreted frame) 
- sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run() @bci=1, line=341 (Interpreted frame) 
- java.lang.Thread.run() @bci=11, line=662 (Interpreted frame) 

Thread 22901: (state = IN_NATIVE) 
- sun.nio.ch.EPollArrayWrapper.epollWait(long, int, long, int) @bci=0 (Compiled frame; information may be imprecise) 
- sun.nio.ch.EPollArrayWrapper.poll(long) @bci=18, line=210 (Compiled frame) 
- sun.nio.ch.EPollSelectorImpl.doSelect(long) @bci=28, line=65 (Compiled frame) 
- sun.nio.ch.SelectorImpl.lockAndDoSelect(long) @bci=37, line=69 (Compiled frame) 
- sun.nio.ch.SelectorImpl.select(long) @bci=30, line=80 (Compiled frame) 
- net.spy.memcached.MemcachedConnection.handleIO() @bci=126, line=188 (Compiled frame) 
- net.spy.memcached.MemcachedClient.run() @bci=11, line=1591 (Compiled frame) 

Answer 1

它可以在調試這種事情幫助，如果你收集一堆的VM信息使用類似jmxtrans每5分鐘和圖形的數據像Graphite這樣的東西。

你可能認爲沒有什麼可辨別的，但這可能是因爲你只查看一個數據點，即響應時間。收集JVM通過JMX公開的所有不同的GC相關數據點，並查看它們中的一個是否提供了一些警告。如果您的應用程序定期分配並釋放相同數量（x％）的堆，則可能與佔可用堆空間的x％有關。您需要研究各種尺度的圖表（放大和縮小）以瞭解您的應用的正常行爲。

Answer 2

回答我自己的問題，因爲我們部分找到了問題的根源。我們必須像我們的系統下面的一段代碼：

LinkedList<Foo> foo = getSomePotentiallyLargeList(); 
long someValue = someCalendar.getTimeInMillis(); 
for (int i = 0; i < foo.size; i++) { 
    if (foo.get(i).someField < someValue) break; 
} 

這實質上是在我們的代碼中的錯誤，因爲上面的for循環需要N^2的時間，因爲foo是一個LinkedList潛在執行。然而，如果我們在一個線程中遇到了一個長列表，它就不應該鎖定我們所有的線程（該線程應該已經被困了很長時間，而其他線程則繼續前進，並且jvm偶爾會暫停gc等）。 ）。

我們的應用程序凍結的原因是當它碰到一個gc時，所有的gc線程都會阻塞，直到所有的線程都到達一個安全點，並且所有的java線程在達到安全點時阻塞，直到gc完成。看起來，JVM無法在for循環中放置一個安全點，以便它需要繼續執行，可能需要幾天或更長時間，直到循環結束並且可以達到安全點。

到達的最後一個安全點位於調用getTimeInMillis（）的內部，所以這就是爲什麼jstack -F報告在那裏的近似執行位置的原因。看起來這肯定是一個JVM錯誤，因爲我的理解是安全點應該位於執行的每個分支中，以防止gc在一個循環線程中等待的這類問題。

不幸的是，我一直無法用自己的小例子在自己的桌面上重現問題。例如，如果我運行兩個線程，其中一個以上述方式執行，另一個線程只分配適量的內存，gc在第一個線程停留在長循環中時不會阻塞第二個線程。

驗證確實是這種情況並隔離問題，或者更好地理解gc觸發後如何確保安全點能夠快速到達將會很好。不用說，我們的解決方案不是在循環中花費n^2次，但是鑑於我們的輸出結果，發現這個特定問題非常困難。 gc不僅停滯不前，而且由於jstack無法在循環內報告jvm的執行位置，因此很難將代碼中的這個錯誤歸零。

Answer 3

嘗試增加

-XX：+ DisableExplicitGC

切換到Java參數。通常，人們在庫代碼中某處遇到了觸發顯式GC的情況，通常時間爲

System.gc（）;

它給JVM提示FULL GC可能會不必要地觸發FULL GC。

-XX：+ DisableExplicitGC將禁用sys調用。