7

最近、jstack -F を使用して取得された次のスタック (他のすべてのスレッドは BLOCKED、IN_NATIVE、または IN_VM です) (コードが開始する場所で切り捨てられます) で、多くのサーバーが散発的かつ突然 (目に見える段階的な劣化ではなく) ロックアップしていることに気付きました。

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 は 2 つのスレッドがあることを示しています。1 つは上記のスレッドのようで、もう 1 つは pstack の次の出力によると、gc スレッドまたは jitc です ( 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;
}

foo が LinkedList であるため、上記の for ループの実行に n^2 時間がかかる可能性があるため、これは本質的にコードのバグです。ただし、1 つのスレッドで 1 つの長いリストに遭遇した場合、すべてのスレッドをロックするべきではありません (そのスレッドは長時間スタックし、他のスレッドは進行を続け、jvm は時々 gc のために一時停止するなど)。 ）。

アプリがフリーズした理由は、gc に到達すると、すべてのスレッドがセーフ ポイントに到達するまですべての gc スレッドがブロックされ、セーフ ポイントに到達すると gc が完了するまですべての Java スレッドがブロックされたためです。どうやら、JVM が for ループ内にセーフ ポイントを設定できなかったため、ループが終了してセーフ ポイントに到達するまで、おそらく数日またはそれ以上実行し続ける必要があったようです。

到達した最後の安全なポイントは、getTimeInMillis() への呼び出しの内部にあったため、jstack -F はそのあたりのおおよその実行場所を報告していました。gc が 1 つのループ スレッドで待機してスタックするというこの種の問題を防ぐために、実行中のすべてのブランチにセーフ ポイントが配置されることになっていることを理解しているため、これは JVM のバグに違いないようです。

残念ながら、私のデスクトップでは、小さな例で問題を再現できませんでした。たとえば、2 つのスレッドを実行し、そのうちの 1 つは上記の方法で実行され、もう 1 つは適度な量のメモリを割り当てているだけの場合、最初のスレッドが長いループでスタックしている間、gc は 2 番目のスレッドをブロックしません。

これが実際に当てはまることを確認して問題を特定するか、gc がトリガーされたときに安全なポイントにすばやく到達できるようにする方法をよりよく理解することをお勧めします。言うまでもなく、私たちの修正はループで n^2 の時間を費やすことではありませんでしたが、出力を考えると、この特定の問題を見つけることは非常に困難でした。gc が動かなくなっただけでなく、jstack がループ内で jvm の実行場所を報告できなかったため、コード内でこのバグを特定するのが困難でした。

于 2012-11-16T00:26:03.597 に答える
1

jmxtrans などを使用して 5 分ごとに大量の VM 情報を収集し、Graphite などでデータをグラフ化すると、この種のデバッグに役立ちます。

識別できるものは何もないと思うかもしれませんが、それはおそらく、1 つのデータ ポイント、つまり応答時間だけを見ているためです。JVM が JMX を介して公開するさまざまな GC 関連のデータポイントをすべて収集し、そのうちの 1 つが警告を発するかどうかを確認します。アプリが定期的に同じ量 (x%) のヒープを割り当てて解放する場合、利用可能なヒープ領域の x% 以内に収まることに関連している可能性があります。アプリの通常の動作を把握するには、さまざまな縮尺 (ズームインおよびズームアウト) でグラフを調べる必要があります。

于 2012-11-15T06:21:50.533 に答える
0

追加してみる

-XX:+DisableExplicitGC

Java パラメータに切り替えます。多くの場合、人々はライブラリ コードのどこかで明示的な GC をトリガーすることに遭遇しました。

System.gc();

これは、不必要に FULL GC をトリガーする可能性がある FULL GC のヒントを JVM に与えます。

-XX:+DisableExplicitGC は、sys コールを無効にします。

于 2013-05-14T01:27:09.413 に答える