Java自身は、オペレーションシステムに複雑な形でアプローチしてくる非常に大きなプログラムです。 通常はかなり安定しているものの、ときにはクラッシュやフリーズなどの問題があることもあります。 Javaアプリケーションがフリーズすると、それを検知して回復することは困難です。 これは、そのJavaプロセス自体が依然としてメモリに存在しており、 多くの一般的なモニタリング(監視)アプリケーションでは応答停止を検知できないこともあります。

JVMのフリーズが発生すると、通常は、ユーザーあるいは、 そのアプリケーションと通信している他のシステムが通信停滞を検知して、そのフリーズの事実に気づきます。 一旦、問題が発覚すると、ときにはユーザーからのクレームにもなり、 システム管理者はサーバーへ接続して、JVMのフリーズを解き、アプリケーションを再起動させます。 もしシステム管理者が不在の場合には、この処理方法では、回復までに数時間を要することもあります。

ソリューション

この問題のソリューションは、Java動作について知り尽くしているモニタリング(監視)アプリケーションを導入し、 24時間365日、アプリケーションのモニタリング(監視)を安心して任せ、問題が発生したときに自動的に処置をしてくれることです。

Java Service Wrapperには、いくつかのモニタリング(監視)機能を備えています。 その機能の1つが、JVMフリーズ検知機能です。 Java Service Wrapperには、JVMフリーズを判断する高度なロジックが組み込まれており、 定期的にJVMをモニタリング(監視)します。 JVMのフリーズを検知すると、自動的にJVMを再起動させ、 最短の停滞時間でシステムをリカバリー(回復)させることができます。 さらに、メール通知機能を設定すれば、 Wrapperからシステム管理者へ状況レポートをメール送信することができるため、 全てが元通りにリカバリー(回復)し、通常どおり動作していることを再確認することができます。

Java Service Wrapperは、 一定間隔でJVMプロセスにping送信して(デフォルト値で5秒毎)、 JVMの応答を確認しています。 もし設定した時間内(デフォルト値で30秒以内)に応答がなかった場合、「JVMがフリーズしている」と判断します。 またWrapperは、誤検出が最小限になるように全体的なシステム負荷についても考慮しています。

JVMフリーズを検知すると、Wrapperはログファイルに次のような記録をとります:

JVMフリーズと再起動が実行されたログ例:
jvm 1    | ...
wrapper  | JVMハングアップの模様: JVMからのシグナル待ちのタイムアウト。
wrapper  | JVM はリクエストに応じて終了しませんでした、中止しました
wrapper  | JVM起動中...
jvm 2    | WrapperManager: 初期化中...
jvm 2    | ...

Wrapperは次のような様々な危機的な問題の検知に役立ちます: フリーズデッドロッククラッシュアプリケーションエラーメモリリークJVM終了コードに応答するなど。

テクニカル概要

フリーズ検知は、デフォルトで有効になっています。 5秒ごとにJVMにping送信して、 30秒以内に応答がないとタイムアウト(時間切れ)となり、 フリーズしているものと判断します。それらのインターバル(一定間隔)時間も柔軟に設定可能です。 もし、wrapper.debug=TRUE]プロパティでデバッグ出力を有効に設定している場合、 ping状態をログファイルで確認することができます。 ここの例では、ログの出力形式は、タイムスタンプを表示するように設定しています。

PINGのログ例:
INFO   | jvm 1    | 2012/05/09 18:28:11 | ...
DEBUG  | wrapperp | 2012/05/09 18:28:13 | パケット送信 PING : ping
INFO   | jvm 1    | 2012/05/09 18:28:13 | WrapperManager デバッグ: パケット受信 PING : ping
INFO   | jvm 1    | 2012/05/09 18:28:13 | WrapperManager デバッグ: パケット送信 PING : ping
DEBUG  | wrapperp | 2012/05/09 18:28:13 | パケット読み PING : ping
DEBUG  | wrapperp | 2012/05/09 18:28:18 | パケット送信 PING : ping
INFO   | jvm 1    | 2012/05/09 18:28:18 | WrapperManager デバッグ: パケット受信 PING : ping
INFO   | jvm 1    | 2012/05/09 18:28:18 | WrapperManager デバッグ: パケット送信 PING : ping
DEBUG  | wrapperp | 2012/05/09 18:28:18 | パケット読み PING : ping
DEBUG  | wrapperp | 2012/05/09 18:28:21 |...

フリーズ検知

対応バージョン :1.0.0
対応エディション :プロフェッショナル版スタンダード版コミュニティー版
対応プラットフォーム :WindowsMac OSXLinuxIBM AIXFreeBSDHP-UXSolarisIBM z/Linux

JVMへのPING動作は、非常に軽量であるため、デフォルトどおり、 5秒のインターバル(一定間隔)でJVMをモニタリング(監視)するのがお薦めです。 ご利用のアプリケーション次第で、あるいはシステムが外部の読み込み負荷が高い状況下次第ですが、 ping応答待機のタイムアウト(時間切れ)を調整する必要があるケースもあります。 タイムアウト時間を延長すると、「JVMがフリーズしている」とWrapperが判断するまでの必要な時間量が増えますので、ご理解ください。

以下のとおり、JVMがフリーズしたときに表示されるログ例をご覧ください。 PINGへの応答が停止し、WrapperがJVMの再起動を始めています:

ログ例: フリーズと再起動
DEBUG  | wrapperp | 2012/05/09 19:20:22 | パケット送信 PING : ping
INFO   | jvm 1    | 2012/05/09 19:20:22 | WrapperManager デバッグ: パケット受信 PING : ping
INFO   | jvm 1    | 2012/05/09 19:20:22 | WrapperManager デバッグ: パケット送信 PING : ping
DEBUG  | wrapperp | 2012/05/09 19:20:22 | パケット読み PING : ping
DEBUG  | wrapperp | 2012/05/09 19:20:27 | パケット送信 PING : ping
DEBUG  | wrapperp | 2012/05/09 19:20:31 | パケット送信 PING : ping
DEBUG  | wrapperp | 2012/05/09 19:20:36 | パケット送信 PING : ping
DEBUG  | wrapperp | 2012/05/09 19:20:40 | パケット送信 PING : ping
DEBUG  | wrapperp | 2012/05/09 19:20:44 | パケット送信 PING : ping
DEBUG  | wrapperp | 2012/05/09 19:20:49 | パケット送信 PING : ping
DEBUG  | wrapperp | 2012/05/09 19:20:53 | パケット送信 PING : ping
DEBUG  | wrapperp | 2012/05/09 19:20:58 | パケット送信 PING : ping
ERROR  | wrapper  | 2012/05/09 19:20:59 | JVMハングアップの模様: JVMからのシグナル待ちのタイムアウト。
ERROR  | wrapper  | 2012/05/09 19:21:00 | JVM はリクエストに応じて終了しませんでした、中止しました

体感してみる

実際のJavaアプリケーションでJVMフリーズを再現するのは困難でしょう。 このテストを簡単にするには、Wrapperに同梱されているTestWrapperサンプルアプリケーションをご利用ください。 その他にも様々なテスト機能が含まれており、体感でお試しいただくことができます。

Wrapperをダウンロードして解凍したフォルダに行き、 コンソールからTestWrapperサンプルアプリケーションを起動してください。 Windows上では「bin\TestWrapper.bat」、 UNIXプラットフォーム上では「bin\testwrapper console」を実行してください。

TestWrapperサンプルアプリケーションが開始すると、シンプルなGUI画面が開き、左側にボタンが並んでいるのが見えるでしょう。 「JVMハングアップシミュレート」ボタンクリックして、JVMをフリーズさせてみましょう。

ログ例:フリーズと再起動
jvm 1    | TestWrapper: ダイアログを表示中...
jvm 1    | WrapperManager: 警告: JVMがハングアップしているように見えます...
wrapper  | JVMハングアップの模様: JVMからのシグナル待ちのタイムアウト。
wrapper  | JVM はリクエストに応じて終了しませんでした、中止しました
wrapper  | JVM起動中...
jvm 2    | WrapperManager: 初期化中...
jvm 2    | TestWrapper: 初期化中...

もし、これを自分のJavaアプリケーションで試してみたい場合、 このテストモードに入るために、 WrapperManager.appearHung() を呼び出すことでテストが可能です。

イベントに応答する

対応バージョン :3.3.0
対応エディション :プロフェッショナル版スタンダード版 (未対応)コミュニティー版 (未対応)
対応プラットフォーム :WindowsMac OSXLinuxIBM AIXFreeBSDHP-UXSolarisIBM z/Linux

アプリケーションがフリーズしたりクラッシュしたとき、まれに単純に再起動だけで解決しないケースもあります。 もしテンポラリーファイルが正しく消されないと、あるいはデータベースが不安定のまま残ったりすると、 新しいアプリケーションのインスタンスが、すぐにエラーで落ちてしまうことがあります。 理想ならば、これらの障害に十分対応できるよう、アプリケーションがしっかりと設計されていればいいのですが、 常にそうできるものでもありません。 このようなケースでは、新しくJVMを起動する前に、クリーンアップ作業をする手段が必要です。

Wrapperは、イベントに応じたコマンドを実行することで、これに対応することができます。 様々な場面で、外部コマンドやスクリプトを実行するようにWrapperを設定することが可能です。

もしデバッグのログ出力を閲覧すると、「Enqueue Event 'NNN'」のエントリー記録があります。 これらは、Wrapperのイベントが発生したタイミングを示しています。 JVMフリーズを検知した後に再起動するケースで、新しくJVMインスタンスを起動する前にクリーンアップスクリプトを起動したいならば、 「jvm_restart」イベントを利用します。

次のようにシンプルなバッチファイルを作成して、Wrapperバイナリと同じディレクトリー内に置いてください。 この例では、単純に10秒のクリーンアップタスクを実行しています。本当の実物スクリプトの方がずっと面白いですが。

「cleanupTest.bat」のサンプルスクリプト
@echo off
echo 10秒間のクリーニングアップ中...
rem 10秒間の遅延を引き起こすpingを利用
PING 1.1.1.1 -n 1 -w 10000 >NUL
echo 全てクリーニングアップ完了。

次に、ご利用のコンフィギュレーションファイル「wrapper.conf」に次のプロパティを追加します。

「wrapper.conf」の設定
wrapper.event.jvm_restart.command.argv.1=cleanupTest.bat
wrapper.event.jvm_restart.command.block=TRUE
wrapper.event.jvm_restart.command.loglevel=INFO

では、試してみましょう。フリーズを検知すると、Wrapperは設定されたバッチファイルを実行して、 それが完了するまで、Wrapperが待機しています:

ログ出力例:
wrapper  | JVMハングアップの模様: JVMからのシグナル待ちのタイムアウト。
wrapper  | JVM はリクエストに応じて終了しませんでした、中止しました
wrapper  | イベントコマンド「jvm_restart」: コマンドライン: cleanupTest.bat
wrapper  | イベントコマンド「jvm_restart」: コマンド起動 (pid: 1188) 、15秒間までブロック中...
10秒間のクリーニングアップ中...
全てクリーニングアップ完了。
wrapper  | イベントコマンド「jvm_restart」: 終了コード「0」でコマンド完了
wrapper  | イベントコマンド「jvm_restart」: 終了コード「0」でコマンド完了:  継続中。
wrapper  | JVM起動中...

メール通知

対応バージョン :3.3.0
対応エディション :プロフェッショナル版スタンダード版 (未対応)コミュニティー版 (未対応)
対応プラットフォーム :WindowsMac OSXLinuxIBM AIXFreeBSDHP-UXSolarisIBM z/Linux

フリーズ・イベントに応じた外部コマンドを実行する機能に加えて、 問題発生時にメール通知を送信するように設定することも可能です。 このメールには、シンプルな内容だけでなく、任意の設定次第で、 ログ出力の内容を添付して送信することもできます。

イベント「jvm_killed時にメール通知を受信するには、以下のように設定します:

「wrapper.conf」の設定
wrapper.event.default.email.smtp.host=mail.example.com
wrapper.event.default.email.sender=wrapper-app@example.com
wrapper.event.default.email.recipient=sysadmin@example.com
wrapper.event.jvm_killed.email=TRUE
wrapper.event.jvm_killed.email.subject=あらヤダ!アプリケーションが強制終了されました。
wrapper.event.jvm_killed.email.maillog=ATTACHMENT

これでJVMが落ちるときには、いつでも次のようなメールが送信されます。

イベント「jvm_killed」時のメール内容
Subject: あらヤダ!アプリケーションが強制終了されました。
To: sysadmin@example.com
From: wrapper-app@example.com

Java Service Wrapper イベント通知

ホスト: myserver
アプリ名: testwrapper
         TestWrapperサンプルアプリケーション

イベント: jvm_killed
--

STATUS | wrapper  | 2012/05/15 18:23:42 | ...
INFO   | jvm 1    | 2012/05/15 18:23:47 | WrapperManager: 警告: JVMがハングアップしているように見えます...
ERROR  | wrapper  | 2012/05/15 18:24:24 | JVMハングアップの模様: JVMからのシグナル待ちのタイムアウト。
ERROR  | wrapper  | 2012/05/15 18:24:25 | JVM はリクエストに応じて終了しませんでした、中止しました

障害ばかりでなく、良いニュースを受信することもできます。 次の設定では、JVMが起動してアプリケーションが動作を始めると、その通知として2つ目のメールを送信します。 このようにメールを組み合わせると、サーバー状況を把握でき、とても役に立ちます。 これで、緊急対応が必要か、それともこのままディナーをゆっくり楽しるのか、判断するのに役立ちます。

「wrapper.conf」の設定
wrapper.event.jvm_started.email=TRUE
wrapper.event.jvm_started.email.subject=良いニュースです! アプリケーションが元に戻りました
wrapper.event.jvm_started.email.maillog=ATTACHMENT

Wrapperのメール機能やイベントシステムは、とても強力で柔軟に設定が可能です。 さらに詳しくは、「イベント概要」をご覧ください。

参照:コンフィギュレーション プロパティ