- PR -

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

1|2|3|4|5 次のページへ»
投稿者投稿内容
ひじき
常連さん
会議室デビュー日: 2006/12/04
投稿数: 22
投稿日時: 2006-12-04 13:30
いつもお世話になっております。

Linux 上で Apache + Tomcat + PostgreSQL を使用した
Web アプリケーションが動作しており、
半年くらい前より Tomcat 上の特定のアプリケーションが
ハングする現象が発生しております。

環境は以下の通りです。
OS : Redhat Linux 9
APPServer : Tomcat 5.0.28
HTTPServer : Apache 2.0.48
mod_jk2 2.0.2
DBServer : PostgreSQL8.4
JDK : JDK 1.4.2_10
FrameWork : Struts 1.1
（サーバ自体は日々再起動を実施しております）

ここ半年間、設定ファイルの変更や
プログラムの見直し等行っているのですが
状況が変わりません。

ハング時の症状としましては以下の通りです。
* 発生頻度としては 月に 1 〜 2 回で
傾向的には午前中に多い。
* 80 及び 8080 ポートにてリクエストしても
レスポンスが帰ってこない。（待ち状態）
よって、何度もアクセスするとApache及びTomcatの
リクエストが溜まりつづけ、最大接続数を
超えてしまう。
（Apache /server-status では W ステータスのプロセスが大量）
* Linux 上で Top コマンドをたたいてみても
特に負荷の高いプロセスは見あたらず、
Apache、Tomcat、PostgreSQL のプロセスもダウンしていない。
* Apache で別システム（PHP）が動作しているが
正常に動作している。
* Tomcat Manager 画面へは接続可。
* Tomcat 上の他のサンプルアプリケーションの内
別の アプリケーション servlet-examples 等は
正常に動作する。
* PostgreSQL へは PGAdmin にて接続可能。
* JVM はダウンしてない
* Apache アクセスログ、エラーログ、
Tomcat の catalina.out 、
PostgreSQL のログを参照する限りでは
特に不具合を特定できるログは出力されていない。

こういった状況になった場合、Tomcat の再起動もしくは
サーバ自体を再起動して復帰させております。

なお、直近でシステムがハングした際に
Tomcat プロセスのスレッドダンプを採取した結果は
以下の通りとなります。

-----
Full thread dump Java HotSpot(TM) Server VM (1.4.2_10-b03 mixed mode):

"TP-Processor264" daemon prio=1 tid=0x086d4548 nid=0x30a waiting on condition [75dfe000..75dff014]
at org.apache.struts.action.Action.isTokenValid(Action.java:671)
at xxx.xxx.xxxxx.xxxxx.presentation.XXXXXAction.execute(XXXXXAction.java:115)
at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:484)
at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:274)
at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482)
at org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:525)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at xxx.xxx.xxxxx.xxxxx.presentaiton.filter.MultipartFilter.doFilter(MultipartFilter.java:49)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at xxx.xxx.xxxxx.xxxxx.presentaiton.filter.AuthFilter.doFilter(AuthFilter.java:156)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at xxx.xxx.xxxxx.xxxxx.presentaiton.filter.ExceptionHandlingFilter.doFilter(ExceptionHandlingFilter.java:62)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at xxx.xxx.xxxxx.xxxxx.presentaiton.filter.CounterManagingFilter.doFilter(CounterManagingFilter.java:49)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at xxx.xxx.xxxxx.xxxxx.presentaiton.filter.CharactorEncodingFilter.doFilter(CharactorEncodingFilter.java:57)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:214)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.StandardContextValve.invokeInternal(StandardContextValve.java:198)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:152)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:118)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:929)
at org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:160)
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:300)
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:374)
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:743)
at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:675)
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-Processor263" - "TP-Processor1" まで同様。

"http-8080-Monitor" prio=1 tid=0x6ad78120 nid=0x30a in Object.wait() [6be7f000..6be7f514]
at java.lang.Object.wait(Native Method)
- waiting on <0x55b0f1f8> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable)
at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:559)
- locked <0x55b0f1f8> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable)
at java.lang.Thread.run(Thread.java:534)

"http-8080-Processor25" daemon prio=1 tid=0x6ad775d0 nid=0x30a runnable [6bdff000..6bdff594]
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:353)
- locked <0x55b0f280> (a java.net.PlainSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:448)
at java.net.ServerSocket.accept(ServerSocket.java:419)
at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:60)
at org.apache.tomcat.util.net.PoolTcpEndpoint.acceptSocket(PoolTcpEndpoint.java:368)
at org.apache.tomcat.util.net.TcpWorkerThread.runIt(PoolTcpEndpoint.java:549)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683)
at java.lang.Thread.run(Thread.java:534)

"http-8080-Processor24" daemon prio=1 tid=0x6ad76a80 nid=0x30a in Object.wait() [6bd7f000..6bd7f614]
at java.lang.Object.wait(Native Method)
- waiting on <0x55b0f450> (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 <0x55b0f450> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Thread.run(Thread.java:534)

"http-8080-Processor23" - "http-8080-Processor1" まで同様。

"ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=1 tid=0x6aa4d3a0 nid=0x30a waiting on condition [6a97f000..6a97f214]
at java.lang.Thread.sleep(Native Method)
at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1597)
at java.lang.Thread.run(Thread.java:534)

"Signal Dispatcher" daemon prio=1 tid=0x080cb820 nid=0x30a waiting on condition [0..0]

"Finalizer" daemon prio=1 tid=0x080c7520 nid=0x30a in Object.wait() [412fb000..412fb594]
at java.lang.Object.wait(Native Method)
- waiting on <0x55b101b0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:111)
- locked <0x55b101b0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:127)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=1 tid=0x080c7160 nid=0x30a in Object.wait() [4127b000..4127b614]
at java.lang.Object.wait(Native Method)
- waiting on <0x55aed000> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:429)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:115)
- locked <0x55aed000> (a java.lang.ref.Reference$Lock)

"main" prio=1 tid=0x0805b3a8 nid=0x30a runnable [bfffb000..bfffbc38]
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:353)
- locked <0x55b102a8> (a java.net.PlainSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:448)
at java.net.ServerSocket.accept(ServerSocket.java:419)
at org.apache.catalina.core.StandardServer.await(StandardServer.java:513)
at org.apache.catalina.startup.Catalina.await(Catalina.java:619)
at org.apache.catalina.startup.Catalina.start(Catalina.java:579)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:324)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:287)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:425)

"VM Thread" prio=1 tid=0x080c6708 nid=0x30a runnable

"VM Periodic Task Thread" prio=1 tid=0x080cfd00 nid=0x30a waiting on condition
"Suspend Checker Thread" prio=1 tid=0x080cae90 nid=0x30a runnable
-----

上記スレッドダンプは 10 秒に一度ぐらいずつ計 6 回
スレッドダンプを採取しましたが、スレッドの状態遷移は
特に見られません。

気になるところは
org.apache.struts.action.Action.isTokenValid にて
すべてのオブジェクトが Wait 状態になっていることです。
何か関係があるのでしょうか。

当方、完全にお手上げ状態です。
存知の方がいらっしゃいましたら、是非ともご教授お願い致します。
nagise
ぬし
会議室デビュー日: 2006/05/19
投稿数: 1141
投稿日時: 2006-12-04 13:46
引用:

未記入さんの書き込み (2006-12-04 13:30) より:
気になるところは
org.apache.struts.action.Action.isTokenValid にて
すべてのオブジェクトが Wait 状態になっていることです。
何か関係があるのでしょうか。


はっきりしたことは言えませんが、該当アプリケーション以外が正常動作している
という点からするとデッドロックしているんじゃないでしょうか。

org.apache.struts.action.Action.isTokenValidのドキュメントを参照すると
http://www.ingrid.org/jajakarta/struts/struts1.0/ja/target/documentation/api/org/apache/struts/action/Action.html#isTokenValid(javax.servlet.http.HttpServletRequest)

引用:

ユーザの現在のセッションにトランザクショントークンが保持されていて、 かつこのアクションのリクエストパラメータとして送信された値がそのトークンとマッチする場合に trueを返します。


このStrutsのトランザクショントークン、私は使ったことがないのですが、
単純に考えて同期されているはずですから、このあたりのロックに使われている
オブジェクトをどこかでロックするようになっているとか、
そういうあたりじゃないかなぁと思います。
まずはActionクラスのドキュメントにあるように

引用:

コントローラは同時に発生した複数のリクエストに対して同一のインスタンスを共有するため、Actionはスレッドセーフであるようにプログラムすべきです。 すなわち次の項目に従って設計すべきです。

リクエストの状態に関連する情報を保持するためにインスタンス変数やスタティック変数を使用してはいけません。インスタンス変数やスタティック変数は同一のアクションに関してリクエストをまたがってグローバルなリソースを共有したい場合に使用します。
他のリソース（JavaBeans、セッション変数等）へのアクセスは、それらが保護を要求する場合は同期化しなくてはいけません（しかしながら、一般的にリソースクラスは必要に応じて自分自身を保護するように設計すべきです）。


というところをチェックしてはどうでしょうか。
ひじき
常連さん
会議室デビュー日: 2006/12/04
投稿数: 22
投稿日時: 2006-12-04 15:00
nagise 様ご回答いただきありがとうございます。
お教えいただきました情報から再度確認してみます。
山本 裕介
ぬし
会議室デビュー日: 2003/05/22
投稿数: 2415
お住まい・勤務地: 恵比寿
投稿日時: 2006-12-04 15:09
デッドロックしている場合は一つ取得すればデッドロックしているかどうかわかりますが、ハング状態のスレッドはわかりません。
既に実施されているかもしれませんが、どのスレッドがハングしているかどうか調べるにはスレッドダンプを複数回取得しましょう。

あと、スレッドが264コも起動しているのはちょっと異常ではないでしょうか？
あまりにスレッド数が多いと逆にパフォーマンスが落ちてしまいます。
十分に負荷テストをして最適値を見つけた結果ということでなければスレッド数は最大でも50〜100程度に設定することをオススメします。
ひじき
常連さん
会議室デビュー日: 2006/12/04
投稿数: 22
投稿日時: 2006-12-04 15:24
インギさんご回答いただきありがとうございます。
引用:

デッドロックしている場合は一つ取得すればデッドロックしているかどうかわかりますが、ハング状態のスレッドはわかりません。

確かにスレッドダンプにはデッドロックしている旨のログは出力されておりませんでした。
ですので、ハング状態と判断した次第です。

引用:

既に実施されているかもしれませんが、どのスレッドがハングしているかどうか調べるにはスレッドダンプを複数回取得しましょう。

こちらについては既に実施済みでして、10秒間隔くらいで 6 回取得しております。
http://yusuke.homeip.net/samurai/ にてスレッドの状態遷移を確認しましたが、すべてのスレッドがハングしているようです。

引用:

あと、スレッドが264コも起動しているのはちょっと異常ではないでしょうか？
あまりにスレッド数が多いと逆にパフォーマンスが落ちてしまいます。
十分に負荷テストをして最適値を見つけた結果ということでなければスレッド数は最大でも50〜100程度に設定することをオススメします。

以前、同現象が発生した際に、Apache にて最大接続数 Over のエラーが出力されており、
その際に変更したものです。最大接続数を増やしたところで問題解決にはなりませんでしたので、近いうちに設定を 50 〜 100 程度に戻すように致します。御指摘ありがとうございます。


nagise
ぬし
会議室デビュー日: 2006/05/19
投稿数: 1141
投稿日時: 2006-12-04 15:50
引用:

インギさんの書き込み (2006-12-04 15:09) より:
デッドロックしている場合は一つ取得すればデッドロックしているかどうかわかりますが、ハング状態のスレッドはわかりません。


私も無知なものですからよく分かっていないのですが、
スレッドの状態として「アクティブ」「ロック」以外に
「ハング」ということがあるのですか？
（状態という言い方は語弊があるのかもしれませんが…）

VMのスレッドの管理機構にバグがない系においてハングすることは
ないと思っていますが、正しいでしょうか。

VMになにかしらバグがあって、特定のスレッドがハングする、
というのであればわからなくはないのですが、スレッドが特殊な
状態を取りうるとなると自分の理解を一旦疑っておかないといけないなぁ。
あしゅ
ぬし
会議室デビュー日: 2005/08/05
投稿数: 613
投稿日時: 2006-12-04 16:24
似たような現象のスレッドを見つけました。
http://www.atmarkit.co.jp/bbs/phpBB/viewtopic.php?topic=20759&forum=12&8

http://www.mail-archive.com/java-linux@java.blackdown.org/msg15589.html
この辺りの方法を試されてはいかがでしょうか。

Redhat 9は2.6系のカーネルからバックポートされたNPTLを使っているので、
その辺りが原因となっているのかもしれません。
山本 裕介
ぬし
会議室デビュー日: 2003/05/22
投稿数: 2415
お住まい・勤務地: 恵比寿
投稿日時: 2006-12-04 17:58
>VMのスレッドの管理機構にバグがない系においてハングすることは
>ないと思っていますが、正しいでしょうか。
ご認識の通りスレッドダンプに現れるスレッドの状態として「ハング」というものはありません。
ただ、Oracle からのレスポンス待ちであったり重い処理をしていて何度スレッドダンプをとっても毎回同じスタックが現れる場合などはハング状態になっていると言いますね。侍で確認したときに">"が連続して表示されるようなスレッドです。

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

[ メッセージ編集済み 編集者: インギ 編集日時 2006-12-04 18:00 ]
1|2|3|4|5 次のページへ»

スキルアップ／キャリアアップ（JOB@IT）