WebSphere Liberty 21.0.0.9 からトランザクションのピア・リカバリーが利用できるようになったので、早速、動作を確認してみました。
前々回の記事 と 前回の記事では、下記の内容を記載しました。
- ２フェーズ・コミット(2 phase commit)
- ピア・リカバリー
- 検証環境
- ピア・リカバリーできない状態での動作を確認 (再起動によるリカバリーの確認)
この記事では、最終目的である、ピア・リカバリーの動作を確認します。
ピア・リカバリーの動作を確認
ピア・リカバリーの動作を確認するので、WebSphere Liberty を２つ起動し、一方の WebSphere Liberty が稼働するノードを停止させることで障害をシミュレートします。
検証で使用する環境は、下図のようになります。検証環境や WebSphere Liberty の構成は、前々回の記事 を参照してください。
WebSphere Liberty を２つ起動
２つの WebSphere Liberty を起動すると、下記の５つのテーブルが DB tranlog 内に作成されました。前回の結果から予測される通りかと思います。
| テーブル名 | 補足 |
|---|---|
| WAS_LEASES_LOG | ドキュメントには説明がありません。下記参照。 |
| WAS_PARTNER_LOGMYLIBERTYPVIBMWEBSPH0 | パートナー・ログ (Pod my-liberty-pv-ibm-websph-0 用) |
| WAS_PARTNER_LOGMYLIBERTYPVIBMWEBSPH1 | パートナー・ログ (Pod my-liberty-pv-ibm-websph-1 用) |
| WAS_TRAN_LOGMYLIBERTYPVIBMWEBSPH0 | トランザクション・ログ (Pod my-liberty-pv-ibm-websph-0 用) |
| WAS_TRAN_LOGMYLIBERTYPVIBMWEBSPH1 | トランザクション・ログ (Pod my-liberty-pv-ibm-websph-1 用) |
テーブル WAS_LEASES_LOG 内の内容も、起動した Pod に応じて以下のようになっていました。
[db2inst1@db2-db2u-0 - Db2U db2inst1]$ db2 "select * from WAS_LEASES_LOG"
SERVER_IDENTITY RECOVERY_GROUP LEASE_OWNER LEASE_TIME
------------------------- ------------------ ------------------------- --------------------
mylibertypvibmwebsph0 wlp1 mylibertypvibmwebsph0 1632723808420
mylibertypvibmwebsph1 wlp1 mylibertypvibmwebsph1 1632723833455
2 record(s) selected.
LEASE_TIME を時刻(UTC)に変換すると、下記のようになります。今回は、約25秒の差になっていますが、これは起動のタイミング等によって変わるようです。
SERVER_IDENTITY RECOVERY_GROUP LEASE_OWNER LEASE_TIME
------------------------- ------------------- ------------------------- --------------------
mylibertypvibmwebsph0 wlp1 mylibertypvibmwebsph0 9/27/21 6:23:28.420
mylibertypvibmwebsph1 wlp1 mylibertypvibmwebsph1 9/27/21 6:23:53.455
prepare 完了を記録した後にノードを停止
ノード worker-0 を停止させることで障害をシミュレートします。ノード worker-0 で稼働する WebSphere Liberty 上の検証用アプリにアクセスし、「トランザクション・ログに prepare 完了を記録」した後にスリープさせます。その間に、ノード worker-0 を停止することで、障害をシミュレートします。
Db2 と MQ は prepare が完了し、TM からの commit 指示を待つ状態となります。
尚、WebSphere Liberty を kubernetes の StatefulSet で起動していますので、他のノードで自動的に再起動されることはありません。
ノード worker-0 の停止は、WAS_LEASES_LOG テーブルの内容を select しつつ、ノード worker-0 で稼働する Pod の LEASE_TIME のカラムが更新されて直ぐに行いました。但し、手作業なので、更新されてから５秒程度の遅延はあったと思われます。
停止直前の LEASE_TIME の値は 1632724782007 (UTC で 9/27/21 6:39:42 ) でした。
ピア・リカバリーを確認
ノード worker-0 を停止した後に、別ノード worker-1 で稼働する WebSphere Liberty の messages.log を tail しました。しばらくすると、以下の出力があり、ピア・リカバリーが完了したことが確認できました。
bash-4.4$ tail /logs/messages.log -f | grep RecoveryManager
[9/27/21 6:41:14:328 UTC] 00000055 com.ibm.tx.jta.impl.RecoveryManager A WTRN0132I: Transaction recovery for mylibertypvibmwebsph0 initiated with server uuid 3079e6254db5d53cd44e9c346ebb63fc266a8b9a and restart epoch 1
[9/27/21 6:41:14:329 UTC] 00000055 com.ibm.tx.jta.impl.RecoveryManager A WTRN0027I: Transaction service recovering 1 transaction.
[9/27/21 6:41:14:329 UTC] 00000055 com.ibm.tx.jta.impl.RecoveryManager A WTRN0134I: Recovering 5 XA resource manager(s) from the transaction partner logs
当然ながら、Db2 と MQ にも in-doubt なトランザクションは残っておらず、正常にリカバリーされていました。
[db2inst1@db2-db2u-0 - Db2U db2inst1]$ db2 list indoubt transactions
SQL1251W No data returned for heuristic query. SQLSTATE=00000
bash-4.4$ dspmqtrn -e -m QM_TEST
There are no matching prepared or heuristically completed transactions.
また、リカバリーが完了すると、ノード worker-0 で稼働していた WebSphere Liberty 用のテーブル(WAS_PARTNER_LOG??? と WAS_TRAN_LOG???) は削除され、テーブル WAS_LEASES_LOG 内の該当行も削除されていました。
ピア・リカバリーに要した時間
上記の結果から、ピア・リカバリーに要した時間を確認してみると、約1分27秒となりました。
- ノードの停止時刻： 9/27/21 6:39:42 ＋ ５秒程度 より、おおよそ、9/27/21 6:39:47
- ピア・リカバリー完了：9/27/21 6:41:14
今回は LEASE_TIME が更新されて直ぐに障害を発生させましたので、回復時間としては長い方になるではないかと思われますが、トランザクション・ログを引き継いだ側のチェック間隔にもよるので、リカバリー時間の単なる一例として扱うのが適切かと思います。
追記：テーブル WAS_LEASES_LOG への書き込み間隔やチェック間隔などは、server.xml の transaction タグで指定でき、以下のような設定項目があります。上記のテストはデフォルト設定で行ったものです。
- leaseLength (デフォルト：60s)
- leaseCheckInterval (デフォルト：60s)
- leaseRenewalThreshold (デフォルト：90s)
- leaseExpiryThreshold (デフォルト：1回)
参照：Liberty サーバー構成 > トランザクション・マネージャー (transaction)
終わりに
WebSphere Liberty 21.0.0.9 から利用可能となった、トランザクションのピア・リカバリーの正常な動作が確認できました。
気になる点は色々ありますので、機会があれば、もう少し調査してみたいところです。