この記事は品川 Advent Calendar 2019の19日目です。
最近、RDBMSの中でもPostgreSQLを触る機会が多いので、今回はあまり有名じゃなさそうだけど便利なPostgreSQLのツールについて調べてみました。
その名も、pg_waldumpです。少し前のバージョンだとpg_xlogdumpという名前の場合もありますが中身は同じです。
公式ドキュメントはあるのですが、例とかも載っておらずなかなか敷居が高いので簡単に試しつつ触って見ました。
何ができるのか
バイナリ形式で書かれている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のリファレンスを見てみてください。
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(失敗)しているなどということも確認できます。
またいつか、色々な操作をした時のダンプの出力内容やログの細かい読み方に関しても調べてみてまとめてみたいと思います。