Java ハングアップ？

#はじめに
ブラウザからのアクセスに対しての応答がなく、漠然とサーバ側の Java がハングアップしてないですか？と問われる場合があります。 何をもって Java VM を疑っているの？ と言いたくなるのですが、そこには、以下のような順で調査を進めたいという理由であろうと思われます。

• Java VM もしくは、その上で動作しているミドルウエアとしてサポート担当からの見解が必要
• 問題がなければ、その旨の答えでもOK
• サポート担当の見解をもって、次は必要に応じてネットワークもしくはデータベース担当へ問い合わせを行いたい

このような状況として、ありがちな一例を投稿いたします。

Java スレッドダンプ

Java のスレッドダンプが取得できる時点で、Java VM の機能が正しく動作しているわけですから Java VM 自体がハングアップしている状況ではないと言えますが、まずは内容を見てみます。

問題部分のスレッドダンプ

"default task-4" #116 prio=5 os_prio=0 tid=0x0000000003ba3800 nid=0x7894 runnable [0x00007f58c80c7000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at oracle.net.ns.Packet.receive(Packet.java:311)
        at oracle.net.ns.DataPacket.receive(DataPacket.java:105)
        at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:305)
        at oracle.net.ns.NetInputStream.read(NetInputStream.java:249)
        at oracle.net.ns.NetInputStream.read(NetInputStream.java:171)
        at oracle.net.ns.NetInputStream.read(NetInputStream.java:89)
        at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:123)
        at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:79)
        at oracle.jdbc.driver.T4CMAREngineStream.unmarshalUB1(T4CMAREngineStream.java:426)
        at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:390)
        at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:249)
        at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:566)
        at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:202)
        at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:45)
        at oracle.jdbc.driver.T4CStatement.executeForDescribe(T4CStatement.java:766)
        at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:897)
        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1026)
        at oracle.jdbc.driver.OracleStatement.executeQuery(OracleStatement.java:1244)
        - locked <0x00000000fcd35220> (a oracle.jdbc.driver.T4CConnection)
        at oracle.jdbc.driver.OracleStatementWrapper.executeQuery(OracleStatementWrapper.java:420)
        at org.jboss.jca.adapters.jdbc.WrappedStatement.executeQuery(WrappedStatement.java:397)
        at abc.doGet(abc.java:37)
... 後略 ...

この例は abc というサーブレットへアクセスした場合に、応答が得られないという内容ですが、その abc に関わるスタックを見ると上記のような内容です。下から上方向へ、さっくりみると jdbc での doExecuteWithTimeout から NetInputStream.read そして、socketRead0 と、リード待ちとなっています。
数十秒待って、もう一度スレッドダンプを取得してもこの状況に変化がありません。
なんとなく doExecuteWithTimeout があることから jdbc のタイムアウトに達してしまった状況のように思われます。
つまり、以下の５番目の動作で待ち状態のまま次の処理へ進めていません。

1. ブラウザからサーバへ HTTP GET のリクエスト
2. サーブレットは応答内容を作るために jdbc で oracle へ　SQL を投げる。
3. SQL の応答が query-timeout 時間内に得られなかった。
4. タイムアウトの処理として statement.cancel にて jdbc へキャンセルを発行
5. そのキャンセルに対しての応答をまっている。
6. キャンセルへの応答が得られれば、SQLTimeoutException として、その例外処理へ・・・たぶん。

注：statement.cancel は、正しく応答が得られる DB に対して発行することでキャンセルされます

という事は、データベースに問題あったのか？？？と考えてしまうかもしれません。

データベース側からの見解は

スレッドダンプの内容から、その時間帯にデータベース側に異常が発生していないか尋ねてみると・・・
**全く異常はみうけられない。**そもそも 何をもって DB を疑っているの？ と言われてしまいました。

キャンセルのパケットは送信されているんだろうか？

データベースに問題がないのであれば、本当に statement.cancel が実行されパケットとしてもデータベースへ送信されているのかが気になります。そこで、問題を再現させパケットをキャプチャして確認します。

Javaが動作しているシステム側では

statement.cancel に対応したパケット

13:14:08.948939 IP rhel74.38860 > 192.168.1.25.1521: Flags [P.U], seq 4510:4511, ack 5404, win 44020, urg 1, length 1
..s....
        0x0010:  c0a8 0119 97cc 05f1 f070 d6a2 c3a2 111d  ......-..p......
        0x0020:  5038 abf4 cdeb 0001 21                   P8......!

Flags [P.U] に注目しますが、P.U つまり PUSH と URG フラグがセットされています。
そしてユーザデータは、 "!" の文字１文字です。
この内容から statement.cancel が実行され、正しくキャンセルのリクエストが送信されている事がわかります。

受け取る側では？
データベース側のシステムでパケットキャプチャを取得し確認すると、上記に対応するパケットが見つかりません。
NAT やら複数のネットワーク機器を通過しているためどこかで捨てられているようすです。
※ わたしの経験的には TCP の URG フラグのみが落とされていたパターンも見たことがあります。URG がセットされていない "!" パケットでは、oracle データベース側は反応しません。

このように、データベースへのステートメント・キャンセルが期待どおりに到達していないと、非常に時間のかかる SQL に対しては、タイムアウトしてキャンセルすることもできず、延々と応答をまってしまう結果となります。

問題はネットワークにある

ネットワーク経路中の NAT やファイヤーウォールなど何かの機構が、この URG フラグつきのパケットを正しく処理できていないのだと思います。
そのため、取得したパケットキャプチャを元にネットワークの担当者に、この URG フラグを含むパケットが到達しないんだけど、と問い合わせることになると思います。
また 何をもってネットワークを疑っているの？ と言われるかもしれませんが・・・

問題が表面化した場合のエラーは多種多様です。

このような jdbc からの応答待ちで、キャンセルも効いていないパターンの場合、一種類の事象のみになるとは限りません。
例えば、トランザクションを開始したのちであれば、JTA (Java Transaction API) により、完了していないトランザクションのリカバリを行う設定が可能です。そのリカバリ動作が 30 分間隔で、24 時間経過するまで試みる、などの設定の場合には、リカバリ動作を試みてもまた同じキャンセルの応答で待ちになります。さらに30分経過する度に、リカバリ用のスレッドが増加して行き、最終的に多くのスレッドが作成された結果 Too Many open files のエラーや、Unable to create new native thread などのリソース面でのエラーに至る場合もあります。
また、24 時間経過するまで諦めませんので、再起動しても同じ動作を繰り返すことになります。

このような点もふまえて時間経過とスレッドダンプの内容を確認し、何が起こっているのかを把握することが大切だと思います。

以上、何かのお役に立ちましたら幸いです。