LoginSignup
3
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 1 year has passed since last update.

@splendormyinIBM

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

Posted at

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

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

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

SQL トレースを確認した部分

トランザクション・ログ保管用DBへのアクセスは、以下のパートに分割できると思われます。

  • Liberty 起動時の処理
  • 個々のトランザクションの処理
  • ピア・リカバリー関連の定期処理1
  • Liberty 停止時の処理
  • トランザクションのリカバリー時の処理
    • 再起動によるリカバリーの場合
    • ピア・リカバリーの場合

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

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

また、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
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
Statement の
バッチ実行2 		INSERT INTO WAS_TRAN_LOG_WLP1 (SERVER_NAME, SERVICE_ID, RU_ID, RUSECTION_ID, RUSECTION_DATA_INDEX, DATA) VALUES (?,?,?,?,?,?)
1回 commit

まとめると、最初のトランザクション処理で発行される 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
Statement の
バッチ実行3 		DELETE FROM WAS_TRAN_LOG_WLP1 WHERE SERVER_NAME = ? AND SERVICE_ID = ? AND RU_ID = ?
(d) （RMの数+1）回 Prepared
Statement の
バッチ実行3 		INSERT INTO WAS_TRAN_LOG_WLP1 (SERVER_NAME, SERVICE_ID, RU_ID, RUSECTION_ID, RUSECTION_DATA_INDEX, DATA) VALUES (?,?,?,?,?,?)
1回 commit

(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
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 される行数が想定より多かったりと、新たな発見も少しでしたがありました。

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

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

  3. 右記の DELETE 文 1 回と INSERT 文（RMの数＋１）回を、まとめてバッチ実行 ↩ ↩2

3
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
3
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?