WebSphere Liberty のトランザクション・ログ I/O の SQL トレースを取得してみた


下記の記事を執筆してから、WebSphere Liberty がトランザクション・ログ保管用データベースに対して、どのような SQL を発行しているのか確認して見たいと思っていました。

- [WebSphere Liberty でトランザクションのピア・リカバリーを試してみる](https://qiita.com/splendormy/items/d1d6d76de43e32a7d553)

WebSphere Liberty はオープンソースの Open Liberty をベースとしているので、github 上のソースで確認するという方法もあるのですが、サッと探した範囲では見つからず、SQL トレースを取得して確認することにしました。

尚、WebSphere Liberty のトランザクション・ログを DB に保管する方法に関しては、以下の WebSphere Liberty のドキュメントに記載されています。

- [リレーショナル・データベースへのトランザクション・ログの保管](https://www.ibm.com/docs/ja/was-liberty/base?topic=liberty-storing-transaction-logs-in-relational-database)

## SQL トレースを確認した部分
トランザクション・ログ保管用DBへのアクセスは、以下のパートに分割できると思われます。
* Liberty 起動時の処理
* 個々のトランザクションの処理
* ピア・リカバリー関連の定期処理[^1]
* Liberty 停止時の処理
* トランザクションのリカバリー時の処理
    * 再起動によるリカバリーの場合
    * ピア・リカバリーの場合 

[^1]: ピア・リカバリーを有効にした場合に定期的に行われる処理

起動・停止時やリカバリー時に発行される SQL にも少しは興味がありますが、やはり一番気になるのは、パフォーマンスに直接関連する個々のトランザクション処理時に発行される SQL だと思います。
このため、今回は、個々のトランザクション処理時に発行される SQL と ピア・リカバリー関連の定期処理で発行される SQL を調べてみました。
取得した SQL トレースは下記の github で公開していますので、気になる方はそちらを参照ください。

- [liberty-tranlog-sql-trace](https://github.com/splendormy/liberty-tranlog-sql-trace)

アプリは、以前の記事で紹介したインダウト生成用アプリを使用しました。

- [WebSphere Liberty 用のインダウト生成アプリ](https://qiita.com/splendormy/items/62954937a896389b9be4)

また、SQL トレースは、以下の２つのトランザクション・パターンで取得しました

* ４つの RM にアクセスするトランザクション
   * １つの MOM だけにアクセスするパターン（１つの MOM と３つの Dummy RM にアクセスするパターン）を使用
* ５つの RM にアクセスするトランザクション
   * テンプレート用のパターン（5 つの Dummy RM にアクセスするパターン）を使用

## 最初のトランザクション処理で発行される SQL
最初のトランザクションでは、トランザクションに参加した RM の情報がパートナー・ログに書き込まれるため、それ以降のトランザクションの時よりも、発行される SQL の数が多くなります。

パートナー・ログへの RM 情報の保存では、**トランザクションに参加した RM の数だけ** 、下表に示す SQL が発行されていました。
４つの RM にアクセスするトランザクションであれば４セット、５つの RM にアクセスするトランザクションであれば５セットの SQL が発行されることになります。
尚、DATA カラムに保管されるデータの量は、RM のリソース定義内容に依存して変わります。

|ID|実行回数|形態|SQL|
|---|---|---|---|
|(a)|RM毎に1回|Statement|SELECT SERVER_NAME FROM WAS_PARTNER_LOG_WLP1 WHERE RU_ID=-1 FOR UPDATE|
|(b)|RM毎に1回|Prepared<br/>Statement|INSERT INTO WAS_PARTNER_LOG_WLP1 (SERVER_NAME, SERVICE_ID, RU_ID, RUSECTION_ID, RUSECTION_DATA_INDEX, DATA) VALUES (?,?,?,?,?,?)|
||RM毎に1回||commit|

トランザクション・ログ本体へのアクセスでは、下表に示す SQL が発行されていました。

|ID|実行回数|形態|SQL|
|---|---|---|---|
|(c)|1回|Statement|SELECT SERVER_NAME FROM WAS_TRAN_LOG_WLP1 WHERE RU_ID=-1 FOR UPDATE|
|(d)|（RMの数+1）回|Prepared<br/>Statement の<br/>バッチ実行[^2]|INSERT INTO WAS_TRAN_LOG_WLP1 (SERVER_NAME, SERVICE_ID, RU_ID, RUSECTION_ID, RUSECTION_DATA_INDEX, DATA) VALUES (?,?,?,?,?,?)|
||1回|commit|

[^2]: 右記の INSERT 文（RMの数＋１）回を、まとめてバッチ実行

まとめると、最初のトランザクション処理で発行される SQL は以下の数になります

* 最初のトランザクション処理で発行される SQL
    * SELECT 文：RM の数 + 1
        * (a) の SELECT 文：RM の数
        * (c) の SELECT 文：１
    * INSERT 文：RM の数 × 2 + 1
        * (b) の INSERT 文：RM の数
        * (d) の INSERT 文：RM の数 + 1
    * commit：RM の数 + 1

(a) と (c) の SELECT FOR UPDATE 文は、Prepared Statement ではなく、単なる Statement として、トランザクション・ログ I/O の塊の最初に必ず実行されています。また、取得する値も常に同じもの（条件 RU_ID=-1 を満たす行の SERVER_NAME カラムの値で、Liberty サーバーの名前、例えば、"defaultServer"）です。
この処理は、トランザクション・ログへのアクセス可否をチェックしたり、トランザクション・ログへ排他的にアクセスするために実行されているのではないかと推測されますが、正確な意図は良く分かりません。


## ２回目以降のトランザクション処理で発行される SQL
２回目以降のトランザクションでは、RM が増えない限り、RM の情報をパートナー・ログに書き込むための SQL は実行されません。
その代わりに、完了したトランザクションの情報をトランザクション・ログから削除するための SQL が発行されるようになります。

２回目以降のトランザクション処理では、下表に示す SQL が発行されていました。

|ID|実行回数|形態|SQL|
|---|---|---|---|
|(c)|1回|Statement|SELECT SERVER_NAME FROM WAS_TRAN_LOG_WLP1 WHERE RU_ID=-1 FOR UPDATE|
|(e)|1回|Prepared<br/>Statement の<br/>バッチ実行[^3]|DELETE FROM WAS_TRAN_LOG_WLP1 WHERE SERVER_NAME = ? AND SERVICE_ID = ? AND RU_ID = ?|
|(d)|（RMの数+1）回|Prepared<br/>Statement の<br/>バッチ実行[^3]|INSERT INTO WAS_TRAN_LOG_WLP1 (SERVER_NAME, SERVICE_ID, RU_ID, RUSECTION_ID, RUSECTION_DATA_INDEX, DATA) VALUES (?,?,?,?,?,?)|
||1回|commit|

[^3]: 右記の DELETE 文 1 回と INSERT 文（RMの数＋１）回を、まとめてバッチ実行

(e) の DELETE 文で削除されるのは、前回完了したトランザクションの情報で、（RMの数＋１）件の行が削除されることになります。従来のファイル形式のトランザクション・ログの場合も、I/O 回数を減らす目的で、完了したトランザクションのログ削除は、次のトランザクションの書き込み時に行われると聞いたことがありますが、DB形式になっても同じ動作となっているようです。
通常の環境ではトランザクションが多数並走することになりますので、複数件分がまとめて削除されたり、逆に削除対象が無い場合もあると思われますが、平均すれば１件分が削除されるはずです。

まとめると、２回目以降のトランザクション処理で発行される SQL は以下の数になります

* ２回目以降のトランザクション処理で発行される SQL
    * (c) の SELECT 文：１
    * (e) の DELETE 文：1（平均）
    * (d) の INSERT 文：RM の数 + 1
    * commit：1

## ピア・リカバリー関連の定期処理で発行される SQL
最後は、ピア・リカバリーを構成した場合に定期的に発行される SQL です。
ピア・リカバリーを構成した Liberty サーバーを起動し、定期的に発行される SQL を調べてみました。定期的に発行される SQL の調査が目的なので、トランザクションは実行していません。

定期的に実行されている処理は、(1) 自分の LEASE_TIME の更新処理と (2) 他の Liberty サーバーの LEASE_TIME のチェック処理の２組のようでした。

### (1) 自分の LEASE_TIME の更新処理

|ID|実行回数|形態|SQL|
|---|---|---|---|
|(f)|1回|Statement|SELECT LEASE_TIME, LEASE_OWNER FROM WAS_LEASES_LOG WHERE SERVER_IDENTITY='mylibertypvibmwebsph0' FOR UPDATE OF LEASE_TIME|
|(g)|1回|Prepared<br/>Statement|UPDATE WAS_LEASES_LOG SET LEASE_TIME = ?, RECOVERY_GROUP = ?, LEASE_OWNER = ? WHERE SERVER_IDENTITY='mylibertypvibmwebsph0'|
||1回|commit|

### (2) 他の Liberty サーバーの LEASE_TIME のチェック処理

|ID|実行回数|形態|SQL|
|---|---|---|---|
|(h)|1回|Statement|SELECT SERVER_IDENTITY, LEASE_TIME FROM WAS_LEASES_LOG WHERE RECOVERY_GROUP = 'wlp1'|
||1回|commit|

処理 (1) と処理 (2) は異なるスレッドから定期的に実行され、処理 (1) は 54 秒間隔、処理 (2) は 60秒間隔で実行されていました。処理 (1) の方が10%ほど短い間隔に設定されているのは、なんとなく納得できる点です。

## 終わりに
トランザクション・ログ I/O の SQL トレースを取得して確認してみました。
想定通りであった部分が多かったですが、想定外の SELECT 文が実行されていたり、INSERT される行数が想定より多かったりと、新たな発見も少しでしたがありました。