PostgreSQL でロックしているプロセスのpidを特定する方法

2023-11-01 PostgreSQL

PostgreSQL でロックしているプロセスのpidを特定する方法

ロック競合の確認方法

最近は少なくなった印象ですが昔ながらのレガシーなシステムなどでは、ロック競合がシステム運用に影響を与えることがあります。
本記事では、PostgreSQL でのロック競合に関連する確認方法や、ロック元のプロセスの pid を特定する方法をご紹介したいと思います。

log_lock_waits を on にする

まず PostgreSQL でのロック競合の確認方法ですが、PostgreSQL ログに情報を出力するのが一般的な方法となっています。
postgresql.conf の log_lock_waits を on にすることで、ロック競合が発生した場合に下記のようなログメッセージが出力されるようになります。
※ 先頭の (1) などは、解説のために追加した番号となります。実際の PostgreSQL ログには出力されません。

ロック競合が発生した場合のログメッセージ

(1) 2023-09-26 15:49:21.830 JST [31279] LOG:  process 31279 still waiting for ShareLock on transaction 746 after 1017.560 ms
(2) 2023-09-26 15:49:21.830 JST [31279] DETAIL:  Process holding the lock: 31196. Wait queue: 31279.
(3) 2023-09-26 15:49:21.830 JST [31279] CONTEXT:  while updating tuple (0,1) in relation "test_table_a"
(4) 2023-09-26 15:49:21.830 JST [31279] STATEMENT:  UPDATE test_table_a SET val = 'レコード更新' WHERE i = 1;

各ログメッセージが、どのような意味合いなのかを 1 行ずつ確認していきます。

(1) pid = 31279 のプロセスが「トランザクションに対する ShareLock」を獲得しようとしてから、1,017.560 ms が経過しました。
(2) pid = 31196 のプロセスが「トランザクションに対する ShareLock」を保持しています。その「トランザクションに対する ShareLock」の解放を pid = 31279 のプロセスが待っています。
(3) pid = 31279 のプロセスは、test_table_a を更新しようとしています。
(4) pid = 31279 のプロセスが実行しようとしている SQL です。

なお、上記のログメッセージは、ロック待ちとなってから deadlock_timeout で指定された秒数を経過した場合に出力されます。
上記のログメッセージが表示されたときの deadlock_timeout はデフォルト値の 1 sec でしたので、ログメッセージ内の経過時間も 1 sec 前後となっています。

トランザクションに対する ShareLock とは

SQL を実行した場合に、テーブルやレコードに対してロックがかかるのは、なんとなく理解できるのですが、PostgreSQL ログに出力されたログメッセージには「トランザクションに対する ShareLock」となっています。
このログメッセージに出力されている「トランザクションに対する ShareLock」とは何かについては、公式ドキュメントの pg_locks ビューのページ内に説明がありますので、下記に引用します。
【 PostgreSQL 15.4 文書 - 54.12. pg_locks - 】
https://www.postgresql.jp/document/15/html/view-pg-locks.html

トランザクションの実行中は常に、サーバプロセスはその仮想トランザクションID上に排他的ロックをかけます。もしある永続IDがトランザクションに割り当てられる（普通はトランザクションがデータベースの状態を変化させるときのみに発生します）と、トランザクションは終了するまで永続トランザクションIDに対して排他ロックを保持します。

あるトランザクションが他のトランザクションを特定して終了まで待機しなければならないと判断した場合、他とみなしたトランザクションのIDに対し共有ロックを獲得するように試み、目的を達します。

ロック競合が発生した場合のログメッセージが出力されるまでの流れ

上記の公式ドキュメントの説明をもとに、ロック競合が発生した場合のログメッセージが出力されるまでの流れを確認します。
※ pid = 31196 がロックを保持している側で、pid = 31279 がロックの解放を待っている側です。

pid = 31196は、トランザクション開始時に自分自身のトランザクション ID に対して排他ロックを保持します。
pid = 31279は、SQL を実行しようとした際に pid = 31196 のトランザクションが完了するのを待機する必要があると分かりました。
pid = 31196 のトランザクション ID に対して共有ロック（ShareLock）を保持しようとします。
pid = 31196 のトランザクション ID はすでに排他ロックが保持されているため、pid = 31279 はその排他ロックの解放を待ちます。
pid = 31279 の排他ロック解放待ちの時間が deadlock_timeout を超えた場合、PostgreSQL ログにログメッセージが出力されます。

ロック解放待ちが解消された場合のログメッセージ

また、ロックを取得できた場合にも下記のようなメッセージが PostgreSQL ログに出力されます。
※ 先頭の (1) などは、解説のために追加した番号となります。実際の PostgreSQL ログには出力されません。

(1) 2023-09-26 15:50:56.094 JST [31279] LOG:  process 31279 acquired ShareLock on transaction 746 after 95281.384 ms
(2) 2023-09-26 15:50:56.094 JST [31279] CONTEXT:  while updating tuple (0,1) in relation "test_table_a"
(3) 2023-09-26 15:50:56.094 JST [31279] STATEMENT:  UPDATE test_table_a SET val = 'レコード更新' WHERE i = 1;

各ログメッセージが、どのような意味合いなのかを 1 行ずつ確認していきます。

(1) pid = 31279 のプロセスが、95281.384 ms 経過後に共有ロック（ShareLock）を獲得しました。
(2) pid = 31279 のプロセスは、test_table_a テーブルの (0, 1) にあるレコードを更新しようとしていました。
- 0 番目のブロックの、1 番目のラインポインタが指す位置にあるレコード
(3) pid = 31279 のプロセスが実行していた SQL です。

ロックの競合元となっているプロセスの情報の確認

以上で、ロック競合が発生した場合のログメッセージについて確認できました。
次は、ロック競合が発生した場合に、その競合元となっているプロセスを特定する方法を確認していきたいと思います。

確認する情報

ロックの情報は pg_locks ビューで確認できます。
また、ロック元となっているプロセスの pid を確認するだけなら pg_blocking_pids 関数という関数も用意されています。

まずはロック競合を起こしてみる

事前の準備として、2 つのプロセスで SQL を実行し、意図的にロック競合を起こした状態にしておきます。

プロセスA

=# BEGIN;
=# SELECT * FROM test_table_a WHERE i = 1 FOR UPDATE;

プロセスB

=# BEGIN;
=# SELECT * FROM test_table_a WHERE i = 1 FOR UPDATE;

これでプロセス B が、プロセス A の SQL の完了を待ち続ける状態となりました。
この状態でロックの情報を調べていきます。

pg_blockng_pids 関数でロックの競合元となっているプロセスの pid を取得する。

引数に pid を指定して pg_blockng_pids 関数を実行します。

postgres=# SELECT pid, pg_blocking_pids(pid) FROM pg_stat_activity ;
  pid  | pg_blocking_pids 
-------+------------------
 34059 | {}
 34060 | {}
 34063 | {}
 34066 | {34071}
 34071 | {}
 36004 | {}
 34056 | {}
 34055 | {}
 34058 | {}
(9 rows)

pg_blocking_pids 関数の結果より

pid = 34066 のプロセスは、pid = 34071 のプロセスが保持しているロックの解放を待っている

ことがわかりました。

pg_locks ビューを確認してロックの情報を確認する

今度は pg_locks ビューを確認して、そのプロセスのロックの情報を確認します。
まずはロック元となっている pid = 34071 を確認します。

postgres=# SELECT * FROM pg_locks WHERE pid = 34071;
   locktype    | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction |  pid  |     mode      | granted | fastpath | waitstart 
---------------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-------+---------------+---------+----------+-----------
 virtualxid    |          |          |      |       | 5/9        |               |         |       |          | 5/9                | 34071 | ExclusiveLock | t       | t        | 
 transactionid |          |          |      |       |            |           769 |         |       |          | 5/9                | 34071 | ExclusiveLock | t       | f        | 
 relation      |        5 |    16384 |      |       |            |               |         |       |          | 5/9                | 34071 | RowShareLock  | t       | f        | 
(3 rows)

上記の pg_locks の結果より

仮想トランザクション ID = 5/9 に対する ExclusiveLock を保持している
トランザクション ID = 769 に対する ExclusiveLock を保持している
oid = 16384 のリレーションに対する RowShareLock を保持している

ことを確認できました。

postgres=# SELECT * FROM pg_locks WHERE pid = 34066;
   locktype    | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction |  pid  |        mode         | granted | fastpath |           waitstart           
---------------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-------+---------------------+---------+----------+-------------------------------
 virtualxid    |          |          |      |       | 4/6        |               |         |       |          | 4/6                | 34066 | ExclusiveLock       | t       | t        | 
 tuple         |        5 |    16384 |    0 |     4 |            |               |         |       |          | 4/6                | 34066 | AccessExclusiveLock | t       | f        | 
 transactionid |          |          |      |       |            |           769 |         |       |          | 4/6                | 34066 | ShareLock           | f       | f        | 2023-09-29 16:12:28.245367+09
 relation      |        5 |    16384 |      |       |            |               |         |       |          | 4/6                | 34066 | RowShareLock        | t       | f        | 
(4 rows)

上記の pg_locks の結果より

仮想トランザクション ID = 4/6 に対する ExclusiveLock を保持している
oid = 16384 の 0 番目のブロックの 4 番目のラインポインタが指す位置にあるレコードに対して AccessExclusiveLock を保持している
トランザクション ID = 769 に対する ExclusiveLock の取得待ちとなっている
- waitstart 列でロックの解放待ちとなった日時を確認可能
oid = 16384 のリレーションに対する RowShareLock を保持している

ことを確認できました。
上記の結果より pid = 34066 のプロセスが、トランザクション ID に対するロックを保持できないため、ロック競合が発生していることを確認できました。

ここで疑問点

繰り返しとなりますが、ロック競合の原因はトランザクション ID に対するロックでした。
今回は SELECT ... FOR UPDATE で、いわゆる行レベルのロックを取得しています。
そのため、ロック競合の原因は「レコードに対するロック」に思えるかもしれませんが、実際にはトランザクション ID に対するロックとなっています。

この理由は、公式ドキュメントの pg_locks ビューのページ（上記で引用したのと同じページ）内に説明があります。
【 PostgreSQL 15.4 文書 - 54.12. pg_locks - 】
https://www.postgresql.jp/document/15/html/view-pg-locks.html

タプルはロック対象のオブジェクト種類ですが、行レベルロックについての情報はメモリではなく、ディスクに保存されます。よって行レベルロックは通常、このビューには現れません。もしプロセスが行レベルロックの待ち状態である場合は、その行ロックを保持している永続トランザクションIDを待つ状態で、そのトランザクションはビューに現れます。

そのため、pg_locks ビューで確認した際に、「トランザクション ID に対するロックの解放待ち」と「レコードに対して AccessExclusiveLock ロックを保持している」の二つの条件を満たしているプロセスが、行レベルロックの解放待ちとなっているプロセスといえそうです。

まとめ

本記事では、ロック競合が発生した場合に出力されるログメッセージと、ロック競合の原因となっているプロセスの特定方法などを紹介いたしました。
ただ、本記事で紹介したこと以外にも、PostgreSQL にはロックの仕組みが多々あります。
ロック競合が発生した場合には PostgreSQL というよりも AP 側に原因があることが多い印象ですが、しっかりとロックの仕様を理解して、PostgreSQL の安定稼働させていきたいものです。

TECH BLOG
技術ブログ