java - 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 后不久，top -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

有没有人知道为什么会开始发生这种情况？

我们在 CentOS 版本 5.7 和 6.3 上使用 jdk1.6.0_33，服务器上有 24 个内核(12 个物理内核)。

这里还有一些堆栈，我们的代码被截断了:

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;
}

这本质上是我们代码中的一个错误，因为上面的 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 在循环内的执行位置，因此很难将我们代码中的这个错误归零。