- PR -

Tomcat アプリケーションハングについて

投稿者投稿内容
ひじき
常連さん
会議室デビュー日: 2006/12/04
投稿数: 22
投稿日時: 2006-12-04 18:13
インギさんご回答いただきありがとうございます。
引用:

侍で確認したときに">"が連続して表示されるようなスレッドです。


仰るとおりすべてのスレッドが ">" でした。(6列)

引用:

ハングしているスタックが全て
at org.apache.struts.action.Action.isTokenValid(Action.java:671)
で止まっているのであれば、ソースコードから何をしているか確認してみてはいかがでしょう。
特に待ちが入るような処理が書いていないのでれば VM レベルで忙しくなっているものと考えられます。
たぶんスレッドが多すぎてコンテキストスイッチで忙しいのではないでしょうか・・・?


とりあえず、Struts のソースを解析してみます。
ひじき
常連さん
会議室デビュー日: 2006/12/04
投稿数: 22
投稿日時: 2006-12-04 20:56
org.apache.struts.action.Action.isTokenValid(Action.java:671) 部分を確認してみました。

org.apache.struts.action.Action
引用:


protected boolean isTokenValid(
HttpServletRequest request,
boolean reset) {

return token.isTokenValid(request, reset); // #671
}




org.apache.struts.util.TokenProcessor
引用:

public synchronized boolean isTokenValid(
HttpServletRequest request,
boolean reset) {

// Retrieve the current session for this request
HttpSession session = request.getSession(false);
if (session == null) {
return false;
}

// Retrieve the transaction token from this session, and
// reset it if requested
String saved = (String) session.getAttribute(Globals.TRANSACTION_TOKEN_KEY);
if (saved == null) {
return false;
}

if (reset) {
this.resetToken(request);
}

// Retrieve the transaction token included in this request
String token = request.getParameter(Constants.TOKEN_KEY);
if (token == null) {
return false;
}

return saved.equals(token);
}



TokenProcessor#isTokenValid(HttpServletRequest request, boolean reset)が
synchronized にて実装されており、恐らくここで Wait 状態になっていると考えられます。

となると、いつ Wait 状態になって、いつ処理は終了するのでしょう?
インギさんの言うとおり、まず、プロセス数の最大値を 50 〜 100 にすべきでしょうか?


[ メッセージ編集済み 編集者: ひじき 編集日時 2006-12-04 20:57 ]
nagise
ぬし
会議室デビュー日: 2006/05/19
投稿数: 1141
投稿日時: 2006-12-05 12:18
引用:

インギさんの書き込み (2006-12-04 17:58) より:
>VMのスレッドの管理機構にバグがない系においてハングすることは
>ないと思っていますが、正しいでしょうか。
ご認識の通りスレッドダンプに現れるスレッドの状態として「ハング」というものはありません。
ただ、Oracle からのレスポンス待ちであったり重い処理をしていて何度スレッドダンプをとっても毎回同じスタックが現れる場合などはハング状態になっていると言いますね。侍で確認したときに">"が連続して表示されるようなスレッドです。



なるほど。外部リソースでのロックとかそっち側ですね。

引用:

ひじきさんの書き込み (2006-12-04 20:56) より:
TokenProcessor#isTokenValid(HttpServletRequest request, boolean reset)が
synchronized にて実装されており、恐らくここで Wait 状態になっていると考えられます。

となると、いつ Wait 状態になって、いつ処理は終了するのでしょう?


インスタンスメソッド自体にsynchronizedが付いているので、
TokenProcessorの該当オブジェクトの別のsynchronizedなインスタンスメソッドが
存在すればそちらでロックしている可能性もありますし、どこかで
コード:
TokenProcessor tokenProcessor; // 該当インスタンスが格納されているとする
synchronized (tokenProcessor) {
    // なんらかの処理
}


となっている場所があってもロックできてしまいますね。

ロックしている「どこか」が再開しない限りは止まったままでしょうね。
そしてその「どこか」を探すのが大変なんだ、コレが。

session.getAttribute()の実装がsynchronizedになっていて
デッドロックしているとかってないですかね。
ぱっとみて他に怪しそうなところが見当たらないですが…。
山本 裕介
ぬし
会議室デビュー日: 2003/05/22
投稿数: 2415
お住まい・勤務地: 恵比寿
投稿日時: 2006-12-05 12:20
ロック取得待ちであれば "- waiting to lock" とか表示されそうなものですが、スレッドダンプには表示されていないんでしょうか?
表示されていれば侍を使えば1クリックでロックを取得しているスレッドを辿ることが出来ますね。
表示されていないとすると VM レベルで異常な状態になっている可能性があります。単にロック処理中に非常にビジーになっているだけかもしれませんが。

[ メッセージ編集済み 編集者: インギ 編集日時 2006-12-05 12:28 ]
nagise
ぬし
会議室デビュー日: 2006/05/19
投稿数: 1141
投稿日時: 2006-12-05 12:49
引用:

インギさんの書き込み (2006-12-05 12:20) より:
ロック取得待ちであれば "- waiting to lock" とか表示されそうなものですが、スレッドダンプには表示されていないんでしょうか?
表示されていれば侍を使えば1クリックでロックを取得しているスレッドを辿ることが出来ますね。
表示されていないとすると VM レベルで異常な状態になっている可能性があります。単にロック処理中に非常にビジーになっているだけかもしれませんが。



この侍ってのはなかなか便利ですね。
ロックの取得スレッドが取れるとなればデッドロックは
再現さえさせれれば用意に解決できますね。

ビジーなのだとすればプロセス数を減らした
低負荷な環境を用意して再現させれればよいのかなぁ。

ひじきさんの提示されたStrutsのソースを見る限りでは
システムリソースとかでロックされる余地はなさそうに見えますが…。
山本 裕介
ぬし
会議室デビュー日: 2003/05/22
投稿数: 2415
お住まい・勤務地: 恵比寿
投稿日時: 2006-12-05 14:09
あ、あと OutOfMemoryError が発生して VM が不正な状態になっているということはないでしょうか?
あしゅ
ぬし
会議室デビュー日: 2005/08/05
投稿数: 613
投稿日時: 2006-12-05 14:22
Strutsのソースを確認してもwait()かけている箇所がなかったので、
NPTL絡みの情報を書いてみたのですが、思いっきりスルーされてます・・・。

LD_ASSUME_KERNELで試して見るのが良さそうだと思うのですが。
ひじき
常連さん
会議室デビュー日: 2006/12/04
投稿数: 22
投稿日時: 2006-12-05 15:17
引用:

nagiseさんの書き込み (2006-12-05 12:18) より:
ロックしている「どこか」が再開しない限りは止まったままでしょうね。
そしてその「どこか」を探すのが大変なんだ、コレが。


どうやって探すのでしょうか。。。見当がつきません。

引用:

インギさんの書き込み (2006-12-05 12:20) より:
ロック取得待ちであれば "- waiting to lock" とか表示されそうなものですが、スレッドダンプには表示されていないんでしょうか?


"waiting to lock" は出力されておりませんでした。

再度スレッドダンプを見直しましたところ waiting on condition の他に
以下の状態のスレッドがありました。抜けがありすみません。

"TP-Processor280" daemon prio=1 tid=0x086beaf0 nid=0x30a runnable [765fe000..765fe814]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:183)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:222)
at java.io.BufferedInputStream.read(BufferedInputStream.java:277)
- locked <0x58b3d6b8> (a java.io.BufferedInputStream)
at org.apache.jk.common.ChannelSocket.read(ChannelSocket.java:598)
at org.apache.jk.common.ChannelSocket.receive(ChannelSocket.java:535)
at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:663)
at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:866)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683)
at java.lang.Thread.run(Thread.java:534)
"TP-Processor234" くらいまでで 10 箇所

"TP-Processor276" daemon prio=1 tid=0x086bc9b0 nid=0x30a in Object.wait() [763fe000..763fea14]
at java.lang.Object.wait(Native Method)
- waiting on <0x58b476a0> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Object.wait(Object.java:429)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:655)
- locked <0x58b476a0> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Thread.run(Thread.java:534)
"TP-Processor269" daemon prio=1 tid=0x086b60b8 nid=0x30a in Object.wait() [7607e000..7607ed94]
at java.lang.Object.wait(Native Method)
- waiting on <0x58b597f0> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Object.wait(Object.java:429)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:655)
- locked <0x58b597f0> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Thread.run(Thread.java:534)


引用:

インギさんの書き込み (2006-12-05 12:20) より:
表示されていれば侍を使えば1クリックでロックを取得しているスレッドを辿ることが出来ますね。
表示されていないとすると VM レベルで異常な状態になっている可能性があります。単にロック処理中に非常にビジーになっているだけかもしれませんが。


VM で異常な状態になっているのを確認する方法ってないですよね。。。
もしかしたら、何分か待てば runnable 状態に変わるなんてこともありえますかねぇ?(最長10分くらい待っていたと思います)

引用:

nagiseさんの書き込み (2006-12-05 12:49) より:
ビジーなのだとすればプロセス数を減らした
低負荷な環境を用意して再現させれればよいのかなぁ。


これについては検証できると思いますの再現テストしてみます。

引用:

インギさんの書き込み (2006-12-05 14:09) より:
あ、あと OutOfMemoryError が発生して VM が不正な状態になっているということはないでしょうか?


それも出力されておりません。catalina.out 、システムログ等を何度も確認しておりますがそれらしいエラーは出力されておりません。
VM Abort するわけでもありません。よっぽど Abort してもらったほうが解決しやすい問題だとは思うのですが。。。

引用:

あしゅさんの書き込み (2006-12-05 14:22) より:
Strutsのソースを確認してもwait()かけている箇所がなかったので、
NPTL絡みの情報を書いてみたのですが、思いっきりスルーされてます・・・。

LD_ASSUME_KERNELで試して見るのが良さそうだと思うのですが。


放置してしまい、すみません。
OS まわりのことはあまり詳しくないのですが、NPTLとはスレッドの種類のことでしょうか?
環境変数に追加するのでしょうか?
export LD_ASSUME_KERNEL=X.X.XX

誠に、おはずかしながら知識が足りないようです。
現在どういう問題があって、どういう設定をすると、どういう効果があるのかお教えいただけますでしょうか。

スキルアップ/キャリアアップ(JOB@IT)