7

最近，我们刚刚注意到我们的许多服务器偶尔突然（没有明显的逐渐降级）锁定到以下堆栈（所有其他线程都是 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)

失败似乎是在full 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)
4

3 回答 3

3

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

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

于 2012-11-16T00:26:03.597 回答
1

如果您每 5 分钟使用 jmxtrans 之类的工具收集一堆 VM 信息并用 Graphite 之类的工具绘制数据，它可以帮助调试此类事情。

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

于 2012-11-15T06:21:50.533 回答
0

尝试添加

-XX:+DisableExplicitGC

切换到您的 Java 参数。人们经常在库代码中的某处遇到使用触发显式 GC

System.gc();

这为 JVM 提供了 FULL GC 的提示，这可能会不必要地触发 FULL GC。

-XX:+DisableExplicitGC 将禁用系统调用。

于 2013-05-14T01:27:09.413 回答