PostgreSQLのトランザクションログを見てみた

この記事は[品川 Advent Calendar 2019](https://qiita.com/advent-calendar/2019/shinagawa)の19日目です。

最近、RDBMSの中でもPostgreSQLを触る機会が多いので、今回はあまり有名じゃなさそうだけど便利なPostgreSQLのツールについて調べてみました。

その名も、**pg_waldump**です。少し前のバージョンだとpg_xlogdumpという名前の場合もありますが中身は同じです。
[公式ドキュメント](https://www.postgresql.jp/document/11/html/pgwaldump.html)はあるのですが、例とかも載っておらずなかなか敷居が高いので簡単に試しつつ触って見ました。

# 何ができるのか

バイナリ形式で書かれているWAL(Write Ahead Logging)ログの内容を人間に読めるレベルに翻訳してくれるツールです。
WALログには、データベースで行われた変更内容(トランザクション)が書かれています。
これを見ることで

* データベースで行われていた処理の傾向を調べる
* トラブルが起きた前後の処理状況を推測したり特定する

といったことができたりします。実行されたSQLをすべてログなどに出しておくのは当然色々と現実的ではないので、後からこういった情報を調べられるのは助かったりします。

# 使い方

pg_waldumpはPostgreSQLと一緒にインストールされています。
引数にWALファイルのパスを指定することでWALファイルの中身をdumpできます。WALファイルは`$PGDATA/pg_wal`配下もしくはアーカイブされたWALを使いましょう。

```
$ pg_waldump pg_wal/00000001000000000000000D
```

dumpする内容をオプションで絞り込めるようになっているので見たい情報があらかじめ決まっているのであれば絞り込みも可能です。
どんなオプションがあるかは[pg_waldump](https://www.postgresql.jp/document/11/html/pgwaldump.html)のリファレンスを見てみてください。

## pg_waldumpの読み方

実行するとWALレコードの内容が1行ずつ出力されます。
誰によって実際にどんなデータが挿入されたか、といった情報までは流石に分かりませんが、どんな処理がどこのテーブルに行われたかといった内容は追うことができます。

```
rmgr: Heap        len (rec/tot):     63/    63, tx:     308189, lsn: 0/0D1E9170, prev 0/0D1E9138, desc: INSERT+INIT off 1 flags 0x00, blkref #0: rel 1663/16384/16413 blk 0
```


dumpしたログは基本的に以下の5つの項目で構成されているようです。

* **rmgr**：リソースマネージャーの名前です。リソースマネージャが何かという話は省きますが、ここではログの種類だと思えばいいかと思います。INSERTやUPDATE、DELETEなどの基本的な更新処理は**Heap**でした。`pg_waldump -r list` と打つと一応リソースマネージャ名の一覧が見れたりします。

* **len (rec/tot)**：WALレコードの長さ(byte)です。
xxx / xxx の前半のxxx部分がレコード自体の長さ、後半がレコードの長さにFPIといわれるデータのイメージを加えた合計の長さです。基本的には後半の数値で見れば問題なさそうです。上の例だとFPI部分が0byteのため同じ値になっていました。

* **tx**：PostgreSQL内での処理に割り振られる番号、トランザクションIDです。ログなどにトランザクションIDを出していれば、それと組み合わせることで特定にも役立つかもしれません。

* **lsn**：LSN(Log Sequence Number)というWALログ内のアドレスです。このWALレコードとひとつ前のWALレコードのアドレスが出力されます。こちらを実際に使うことはあまりないかもしれません。

* **desc**：ログに関する詳細情報になります。この内容から処理の内容を大まかに推測できます。

`desc: INSERT+INIT off 1 flags 0x00, blkref #0: rel 1663/16384/16413 blk 0`

上の例だと、何らかのデータのINSERT処理で、`1663/16384/16413`というテーブルに対しての処理ということが読み取れます。
対象のテーブル名は、テーブルスペースのID/データベースのID/テーブルのファイルノードIDという並びになってるのでSQLで後から調べることもできます。

```
test=# SELECT oid,spcname FROM pg_tablespace;
 oid  |  spcname   
------+------------
 1663 | pg_default
 1664 | pg_global
(2 rows)

test=# SELECT oid,datname FROM pg_database;
  oid  |  datname  
-------+-----------
 13593 | postgres
 16384 | test
     1 | template1
 13592 | template0
(4 rows)

test=# SELECT relfilenode,relname  FROM pg_class WHERE relfilenode = 16413;
 relfilenode | relname 
-------------+---------
       16413 | test
(1 row)
```


## 試してみる
実際にどんな風に見えるか見てみましょう。
試しにINSERT,UPDATE,DELETEをしてみます。
環境はcentos7上のpostgresql12.1です。

```
test=# CREATE TABLE test (id int, value int);
CREATE TABLE
test=# BEGIN;
BEGIN
test=# INSERT INTO test VALUES(1,100),(2,240),(3,50);
INSERT 0 3
test=# UPDATE test SET value = value * 2 WHERE id = 1;
UPDATE 1
test=# DELETE FROM test;
DELETE 3
test=# SELECT txid_current_if_assigned();
 txid_current_if_assigned 
--------------------------
                   308189
(1 row)

test=# COMMIT;
COMMIT
test=# \q
```

最後に`txid_current_if_assigned()`でxid(トランザクションID)を確認してあるので、それをもとに関係のあるWALログの内容だけ出力してみます。

```
[test@centos7 pg12]$ pg_waldump pgdata/pg_wal/00000001000000000000000D --xid 308189
rmgr: Heap        len (rec/tot):     63/    63, tx:     308189, lsn: 0/0D1E9170, prev 0/0D1E9138, desc: INSERT+INIT off 1 flags 0x00, blkref #0: rel 1663/16384/16413 blk 0
rmgr: Heap        len (rec/tot):     63/    63, tx:     308189, lsn: 0/0D1E91B0, prev 0/0D1E9170, desc: INSERT off 2 flags 0x00, blkref #0: rel 1663/16384/16413 blk 0
rmgr: Heap        len (rec/tot):     63/    63, tx:     308189, lsn: 0/0D1E91F0, prev 0/0D1E91B0, desc: INSERT off 3 flags 0x00, blkref #0: rel 1663/16384/16413 blk 0
rmgr: Heap        len (rec/tot):     71/    71, tx:     308189, lsn: 0/0D1E9230, prev 0/0D1E91F0, desc: HOT_UPDATE off 1 xmax 308189 flags 0x60 ; new off 4 xmax 0, blkref #0: rel 1663/16384/16413 blk 0
rmgr: Heap        len (rec/tot):     54/    54, tx:     308189, lsn: 0/0D1E9278, prev 0/0D1E9230, desc: DELETE off 2 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/16384/16413 blk 0
rmgr: Heap        len (rec/tot):     54/    54, tx:     308189, lsn: 0/0D1E92B0, prev 0/0D1E9278, desc: DELETE off 3 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/16384/16413 blk 0
rmgr: Heap        len (rec/tot):     54/    54, tx:     308189, lsn: 0/0D1E92E8, prev 0/0D1E92B0, desc: DELETE off 4 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/16384/16413 blk 0
rmgr: Transaction len (rec/tot):     34/    34, tx:     308189, lsn: 0/0D1E9358, prev 0/0D1E9320, desc: COMMIT 2019-12-16 02:02:00.779658 JST
```

順番にdescの内容を見てみると、

* INSERTが3つ
* (HOT) UPDATEが1つ
* DELETEが3つ
* 最後にCOMMIT

となっています。SQL毎というよりは、変更された行ごとに出力されていました。
1行だけ更新するはずがWHERE句の条件が間違って2行更新されていた、DELETEでデータが大量に消されているなどといった業務のミスも後から見つけられそうです。



## walログの傾向も簡単に見れる

**--stat**オプションでどんなWALログが多いかという傾向も見れます。

```
[test@centos7 pg12]$ pg_waldump pgdata/pg_wal/00000001000000000000000D --stat
Type                                           N      (%)          Record size      (%)             FPI size      (%)        Combined size      (%)
----                                           -      ---          -----------      ---             --------      ---        -------------      ---
XLOG                                           5 (  0.03)                  486 (  0.04)                    0 (  0.00)                  486 (  0.02)
Transaction                                 3300 ( 16.53)               113969 (  8.68)                    0 (  0.00)               113969 (  5.84)
Storage                                        3 (  0.02)                  126 (  0.01)                    0 (  0.00)                  126 (  0.01)
CLOG                                           0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
Database                                       0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
Tablespace                                     0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
MultiXact                                      0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
RelMap                                         0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
Standby                                       28 (  0.14)                 1424 (  0.11)                    0 (  0.00)                 1424 (  0.07)
Heap2                                       3326 ( 16.66)               213491 ( 16.25)               482224 ( 75.40)               695715 ( 35.62)
Heap                                       13236 ( 66.32)               980197 ( 74.63)                72584 ( 11.35)              1052781 ( 53.90)
Btree                                         61 (  0.31)                 3754 (  0.29)                84788 ( 13.26)                88542 (  4.53)
Hash                                           0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
Gin                                            0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
Gist                                           0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
Sequence                                       0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
SPGist                                         0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
BRIN                                           0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
CommitTs                                       0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
ReplicationOrigin                              0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
Generic                                        0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
LogicalMessage                                 0 (  0.00)                    0 (  0.00)                    0 (  0.00)                    0 (  0.00)
                                        --------                      --------                      --------                      --------
Total                                      19959                       1313447 [67.25%]               639596 [32.75%]              1953043 [100%]
pg_waldump: fatal: error in WAL record at 0/D1E9468: invalid record length at 0/D1E94A0: wanted 24, got 0
```

左から、ログの種類(Type)、ログの数(N)、Record本体のサイズ(Record size)、FPIのサイズ(FPI size)、合計サイズ(Combined size)です。割合も出てるので見やすいです。容量設計とかする際にWALの量を見積もるためには便利かもしれません。

# まとめ

pg_waldumpを使い、WALの中身を確認してみました。
あらかじめ、PostgreSQLのログファイルにxidを出力するようにしておく(**log_line_prefix**の**%x**)と何かトラブルが起きた時に役に立つかもしれないなと感じました。
他にも、データがDELETEやTRUNCATEされている、トランザクションがABORT(失敗)しているなどということも確認できます。

またいつか、色々な操作をした時のダンプの出力内容やログの細かい読み方に関しても調べてみてまとめてみたいと思います。