JVM在完全gc后偶尔锁定

Question

最近，我们只是注意到我们的许多服务器零星和突然地(没有明显的逐渐降级)锁定以下堆栈(所有其他theads被阻塞、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之后不久，根据pstack的以下输出(不是VMThread：：-H ())，top -p显示有两个线程，一个似乎是上面的线程，另一个是gc线程或jitc：：

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

回答我自己的问题，因为我们部分地找到了问题的根源。我们的系统中有一段如下所示的代码：

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

这本质上是我们代码中的一个bug，因为上面的for循环可能需要n^2个时间来执行，因为foo是一个LinkedList。然而，如果我们在一个线程中遇到一个长列表，它不应该锁定我们所有的线程(该线程应该已经被卡住了很长一段时间，而其他线程仍在继续前进，jvm偶尔会暂停以进行gc，等等)。

我们的应用程序冻结的原因是，当它遇到gc时，所有gc线程都会阻塞，直到所有线程都达到安全点，所有java线程都会在到达安全点时阻塞，直到gc完成。似乎由于某种原因，JVM未能将安全点放入for循环中，因此它将需要继续执行，可能需要几天或更长时间，直到循环结束并到达安全点。

到达的最后一个安全点是在对getTimeInMillis()的调用中，所以这就是为什么jstack -F报告了大约在那里的执行位置。这看起来一定是JVM的bug，因为我的理解是，安全点应该位于执行中的每个分支中，以防止gc在等待一个循环线程时出现这种问题。

不幸的是，我不能用一个小例子在我自己的桌面上重现这个问题。例如，如果我运行两个线程，其中一个以上面的方式执行，另一个只是分配适中的内存，那么gc不会阻塞第二个线程，而第一个线程却陷入了长循环。

如果能验证这一点并隔离问题，或者更好地了解如何确保在触发gc后可以快速到达安全点，那就更好了。不用说，我们的解决方法不是在循环中花费n^2时间，但根据我们的输出，找到这个特定的问题非常困难。不仅gc卡住了，而且因为jstack无法报告jvm在循环中的执行位置，所以很难在我们的代码中发现这个bug。

Answer 2

如果你每隔5分钟收集一批虚拟机信息，比如jmxtrans，并在Graphite之类的东西中绘制数据，那么它可以帮助你调试这类东西。

您可能认为没有什么可辨别的，但这可能是因为您只查看了一个数据点，即响应时间。收集JVM通过JMX公开的所有不同的GC相关数据点，看看其中是否有一个给出了一些警告。如果您的应用程序定期分配和释放相同数量( x% )的堆，这可能与在可用堆空间的x%范围内相关。你需要研究不同比例的图表(放大和缩小)，以了解你的应用程序的正常行为。

Answer 3

尝试添加

-XX:+DisableExplicitGC

切换到您的Java参数。人们经常遇到在库代码中的某个地方使用

System.gc()；

这将提示JVM进行完整的GC，这可能会触发不必要的完整GC。

-XX:+DisableExplicitGC将禁用sys调用。