そごうソフトウェア研究所

SOA、開発プロセス、ITアーキテクチャなどについて書いています。Twitterやってます@rsogo

サーバサイドJavaのトラブル分析（APサーバースローダウン）

ここ１ヶ月くらいサーバーサイドのトラブル解決をよくやっていて、Javaのサーバーアプリのトラブルの分析のやり方を書いていきます。

先日発生したのはAPサーバーのスローダウンでした。ここでの原因は特殊なものだと思うので、その理由よりは分析のプロセスの方が大事かなと思っています。

チェックした内容

  • OSリソースの使用状況

sarを見ると該当の時間でuserのCPU使用率が90％を超えていました。 ioなどに問題はないので、アプリ層に問題がありそうです。

  • gcログ

FullGCが頻発していれば、CPUを使い切っていてスローダウンが発生するが、GCは大したことなかった。

  • topコマンドでプロセスごとのCPU使用量確認

APサーバー（WebLogic Server）のJavaプロセスが使っていることを確認。 でもどのサーバーアプリかは分からない。

  • アプリログ

特にエラーはない。ただし、処理開始・終了のログから処理速度が遅いことは確認

該当の時間にBroken pipeのエラーログが大量にでていた。

Caused By: javax.xml.stream.XMLStreamException: java.net.SocketException: Broken pipe

ただし、Broken pipeが発生するのはネットワークが正常のステップで切断されていない場合（例えば、通信経路にあるFirewallがタイムアウトで接続を切っていたり、クライアントアプリがタイムアウトで接続を閉じた場合など）なので本当の理由は別にあるはずです。

エラーの原因

WebLogic Serverのログをさらにさかのぼって確認すると次のようなログがでていました。

Error Log in case of JDBC Trace Log (MS SQL Server ...

「[STUCK] ExecuteThread: '11' for queue: 'weblogic.kernel.Default (self-tuning)'は"600"秒間ビジー状態になっています。これは、構成された時間(StuckThreadMaxTime)"600"秒を超えています。」というのはWebLogic Serverがあるスレッドが設定された時間（デフォルト600秒）の間、処理がスタックしていればスタック状態と見なすという挙動です。 スタック状態と見なした後は設定に依ってWebLogic Serverを再起動したりをすることができます。

スタックトレースを見ると「com.microsoft.sqlserver.jdbc.SQLServerResultSet」が「java.util.logging.Logger」を使っているところばかりです。 実はWebLogic Server、SQL Server間でエラーが以前発生していたので分析のためのJDBC Traceログを仕掛けていたのですが、その設定が中途半端に残っていました。実際のログは出力されていないが、出力するための設定ファイルを毎回見に行くという状態になっていました。

そのため、io負荷が異常に高ければ、ログ出力を疑ったと思うのですが、実際はioは問題になっておらず、CPUを使い切っているという症状となっていました。

重要なこと

分析に必要な情報がでていること

問題の再現手順が分からないことや、本番環境でしか発生しないなど発生させるのが難しい場合があります。 予め問題の分析に必要な情報が収集されていることが重要です。 設定面で言えば、GCログが出力されるようにセットしていることや、OSやミドルウェアのリソース使用状況が記録されている必要があります。

アプリケーションの設計では、適切なログが出力されるようになっていることも重要です。 エラーのスタックトレースが出力されていて、エラーの箇所が特定できること。 スローダウンが発生している際に、全ての処理が遅いのか、特定のAPIのみかなどが分かること。（そもそもサーバー側の処理時間が分かること）

根気よく効率良く情報を読むこと

まず問題を報告してくれた人に正確な情報を聞くこと。 問題が発生した日時、問題が発生する条件・手順。 後でログを詳しく見る際に、問題が発生した日時が分からないと作業量が膨大です。

自分はまず、関連するログをgrepで「FATAL」、「ERROR」、「Exception」などでざっと検索をかけます。 （プロジェクト終盤のテストのフェーズであれば、エラーの報告の有無に関わらず、毎日ログを検索して想定外のエラーが発生していないか確認します。本来、監視の対象にならないようなログがログレベルを間違って出力されているのもここで確認できます）

それで該当の時間帯にエラーのログが出力されていれば、そこから始めます。 ポイントとして、その後のログを見ていくのでは無く、時系列をさかのぼってログを見ていきます。 もっと前の時間に同じ、または別のエラーが発生していないかを確認します。 これはユーザーに見えているエラーの原因となるエラーがもっと前に発生していることがあるからです。

この例の場合、ユーザーから報告のあった時間にはBroken pipeのエラーがありますが、 もっと前のログを見ると、java.util.Logginのエラーがでています。

今回は問題になっていませんでしたが、作っているアプリの中に問題があった場合はGCログや、スレッドダンプの中身を詳細に見ていく必要があるので、適切なViewerやWebLogic Serverの場合、JRockit Mission Controlなどのツールを使えるようにしておきたいところです。