View WAL

WAL を見る
PostgresSQL Unconference #33 (2022-05-31)

View Slide

自己紹介
● ぬこ＠横浜 (@nuko_yokohama)
● にゃーん
● 趣味でポスグレをやってる者だ
● 家では UNLOGGED TABLE しか使ってない

View Slide

今日のお題
pg_waldump

View Slide

what’s pg_waldump?
● PostgreSQL の WAL(Write Ahead Log) を可視化するツール。
（可視化はするが読めるとは言っていない）
● WAL はバイナリファイルなので、バイナリアンでない人では見るのが大変
● pg_waldump は WAL セグメントファイルを読み、謎の書式で
標準出力に出力してくれる。
● 用途は学習・デバッグ用とのこと。
– 実運用での利用は想定はしていないっぽい。
謎の書式？

View Slide

$ hexdump -C 000000010000000300000062
00000000 0d d1 02 00 01 00 00 00 00 00 00 62 03 00 00 00 |...........b....|
00000010 00 00 00 00 00 00 00 00 17 d9 98 08 cb 9f 99 61 |...............a|
00000020 00 00 00 01 00 20 00 00 72 00 00 00 00 00 00 00 |..... ..r.......|
00000030 00 00 00 00 00 00 00 00 00 00 00 00 7d 13 8e 1b |............}...|
00000040 ff 58 28 00 00 62 03 00 00 00 01 00 00 00 01 00 |.X(..b..........|
（略）
000002b0 60 02 00 62 03 00 00 00 00 01 00 00 76 b3 e2 b0 |`..b........v...|
000002c0 ff 08 e9 a8 96 b7 8b 7d 02 00 00 00 00 00 00 00 |.......}........|
000002d0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
01000000
pg_waldump 実行例
● WAL セグメントファイルの hexdump
謎のバイナリ
ファイル

View Slide

● WAL セグメントファイルの pg_waldump 出力
$ pg_waldump 000000010000000300000062
rmgr: XLOG len (rec/tot): 114/ 114, tx: 0, lsn: 3/62000028, prev
0/00000000,
desc: CHECKPOINT_SHUTDOWN redo 3/62000028; tli 1; prev tli 1; fpw true; xid 0:1104328; oid
17285;
multi 1; offset 0; oldest xid 726 in DB 1; oldest multi 1 in DB 1;
oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
rmgr: XLOG len (rec/tot): 54/ 54, tx: 0, lsn: 3/620000A0, prev
3/62000028,
desc: PARAMETER_CHANGE max_connections=100 max_worker_processes=8 max_wal_senders=10
max_prepared_xacts=0
max_locks_per_xact=64 wal_level=replica wal_log_hints=off track_commit_timestamp=off
rmgr: XLOG len (rec/tot): 114/ 114, tx: 0, lsn: 3/620000D8, prev
3/620000A0,
desc: CHECKPOINT_SHUTDOWN redo 3/620000D8; tli 1; prev tli 1; fpw true; xid 0:1104328; oid
17285;
multi 1; offset 0; oldest xid 726 in DB 1; oldest multi 1 in DB 1;
（略）
pg_waldump 実行例
謎の
テキスト文字列

View Slide

何が謎なのか？
● PostgreSQL 文書には、 pg_waldump の出力形式に関する情報が
一切記載されていない！
– 自分みたいな一般ユーザに優しくない・・・

View Slide

pg_waldump を動かしてみる

View Slide

pg_waldump を動かしてみる
● 基本的には pg_waldump に、 pg_wal ディレクトリ上にある WAL セ
グメントファイル（ 24 桁の 16 進文字列で構成されたファイル名）を
食わせれば良い。
● 何かを実行しながら、 WAL の状態をみたい場合には、 -f (--follow)
オプションをつけて実行する。（ tail -f っぽい動きになる）
● ただ、普通に PostgreSQL サーバを起動した状態で、 pg_waldump を
動かすと、いろんなサーバプロセスから WAL 書き込みが発生して、見
るのが大変・・・
$ cd $PGDATA/pg_wal
$ pg_waldump 000000010000000300000064

View Slide

おすすめ：シングルユーザモードで動かす
● pg_ctl で PostgreSQL サーバを起動しなくても、直接バックエンドプロ
セスを起動する方法がある。
– PostgreSQL サーバを停止させておく。
– postgres --singule -D –
こうすると単一のバックエンドプロセスのみ起動した状態になる。
● この中で DML も DDL も実行できる
$ postgres --single test -D $PGDATA
PostgreSQL stand-alone backend 14.2
backend>

View Slide

実行する SQL 例
● INSERT→UPDATE→DELETE→TRUNCATE の SQL 例
INSERT INTO foo VALUES (1, 'ABC');
BEGIN;
INSERT INTO foo VALUES (2, 'DEF');
INSERT INTO foo VALUES (3, 'XYZ');
COMMIT;
BEGIN;
UPDATE foo SET data = 'xyz';
DELETE FROM foo WHERE id = 1;
COMMIT;
TRUNCATE foo;
● こんな感じの SQL を foo テーブル /bar テーブル（ UNLOGGED ）に
対して実行してみる。

View Slide

実行 (pg_waldump 起動）
● ターミナルは 2 つ上げておく。
● ターミナル 1 で、 pg_wal ディレクトリ上にある、 WAL セグメントファイル名を確認する。
– 予め pg_resetwal で WAL 情報をクリアしておくと見るときに楽。
● https://www.postgresql.org/docs/14/app-pgresetwal.html
– pg_waldump を -f(--follow) モードで実行する。
$ cd $PGDATA/pg_wal
$ ls
000000010000000300000067 archive_status
$ pg_waldump -f 000000010000000300000067
0/00000000, desc: CHECKPOINT_SHUTDOWN redo 3/67000028; tli 1; prev tli 1; fpw true; xid
0:1104336; oid 17307; multi 1; offset 0; oldest xid 726 in DB 1; oldest multi 1 in DB 1;

View Slide

実行（バックエンド起動）
● ターミナル 2 で、バックエンドプロセスをシングルユーザモードで起動する。
$ postgres --single test -D $PGDATA
PostgreSQL stand-alone backend 14.2
backend>
● するとターミナル 1 に何やら出力される。
rmgr: XLOG len (rec/tot): 54/ 54, tx: 0, lsn: 3/660000A0, prev
3/66000028, desc: PARAMETER_CHANGE max_connections=100 max_worker_processes=8
max_wal_senders=10 max_prepared_xacts=0 max_locks_per_xact=64 wal_level=replica
wal_log_hints=off track_commit_timestamp=off
● なんかシングルユーザモードで起動するときに GUC をいくつか変更するらしく、
その操作も WAL に記録するっぽい。しらんけど。

View Slide

実行（ foo への挿入）
● ターミナル 2 で、 foo テーブルに対する INSERT を実行する。
backend> INSERT INTO foo VALUES (1, 'ABC')
backend>
● するとターミナル 1 に何やら出力される。
rmgr: Heap len (rec/tot): 63/ 63, tx: 1104336, lsn: 3/670000D8, prev
3/670000A0, desc: INSERT+INIT off 1 flags 0x00, blkref #0: rel 1663/17235/17293 blk 0
rmgr: Btree len (rec/tot): 90/ 90, tx: 1104336, lsn: 3/67000118, prev
3/670000D8, desc: NEWROOT lev 0, blkref #0: rel 1663/17235/17298 blk 1, blkref #2: rel
1663/17235/17298 blk 0
3/67000118, desc: INSERT_LEAF off 1, blkref #0: rel 1663/17235/17298 blk 1
rmgr: Transaction len (rec/tot): 34/ 34, tx: 1104336, lsn: 3/670001B8, prev
3/67000178, desc: COMMIT 2022-03-21 17:48:34.759330 JST

View Slide

実行（ foo への挿入）
● 1663/17235/17293 と 1663/17235/17298 is 何？
backend> SELECT relname, relkind FROM pg_class WHERE relfilenode = 17293
1: relname (typeid = 19, len = 64, typmod = -1, byval = f)
2: relkind (typeid = 18, len = 1, typmod = -1, byval = t)
----
1: relname = "foo" (typeid = 19, len = 64, typmod = -1, byval = f)
2: relkind = "r" (typeid = 18, len = 1, typmod = -1, byval = t)
----
backend> SELECT relname, relkind FROM pg_class WHERE relfilenode = 17298
1: relname (typeid = 19, len = 64, typmod = -1, byval = f)
2: relkind (typeid = 18, len = 1, typmod = -1, byval = t)
----
1: relname = "foo_pkey" (typeid = 19, len = 64, typmod = -1, byval = f)
2: relkind = "i" (typeid = 18, len = 1, typmod = -1, byval = t)
----
backend>
● それぞれ foo テーブルと foo テーブルの暗黙的インデックス foo_key に対する
なんかが行われたことがわかる。

View Slide

実行（ foo への挿入その 2 ）
● ターミナル 2 で、 foo テーブルに対する BEGIN/INSERT/COMMIT を実行する。
backend> BEGIN
backend> INSERT INTO foo VALUES (2, 'DEF')
backend> INSERT INTO foo VALUES (3, 'XYZ')
backend> COMMIT
backend>
rmgr: Heap len (rec/tot): 63/ 63, tx: 1104337, lsn: 3/670001E0, prev
3/670001B8, desc: INSERT off 2 flags 0x00, blkref #0: rel 1663/17235/17293 blk 0
3/670001E0, desc: INSERT_LEAF off 2, blkref #0: rel 1663/17235/17298 blk 1
rmgr: Heap len (rec/tot): 63/ 63, tx: 1104337, lsn: 3/67000260, prev
3/67000220, desc: INSERT off 3 flags 0x00, blkref #0: rel 1663/17235/17293 blk 0
rmgr: Btree len (rec/tot): 64/ 64, tx: 1104337, lsn: 3/670002A0, prev
3/67000260, desc: INSERT_LEAF off 3, blkref #0: rel 1663/17235/17298 blk 1
rmgr: Transaction len (rec/tot): 34/ 34, tx: 1104337, lsn: 3/670002E0, prev
3/670002A0, desc: COMMIT 2022-03-21 18:08:28.733419 JST

View Slide

実行（ foo への更新と削除）
● ターミナル 2 で、 foo テーブルに対する BEGIN/INSERT/COMMIT を実行する。
backend> BEGIN
backend> UPDATE foo SET data = 'xyz'
backend> DELETE FROM foo WHERE id = 1
backend> COMMIT
3/670002E0, desc: HOT_UPDATE off 1 xmax 1104338 flags 0x20 ; new off 4 xmax 0, blkref #0: rel
1663/17235/17293 blk 0
3/67000308, desc: HOT_UPDATE off 2 xmax 1104338 flags 0x20 ; new off 5 xmax 0, blkref #0: rel
1663/17235/17293 blk 0
3/67000350, desc: HOT_UPDATE off 3 xmax 1104338 flags 0x20 ; new off 6 xmax 0, blkref #0: rel
1663/17235/17293 blk 0
rmgr: Heap len (rec/tot): 54/ 54, tx: 1104338, lsn: 3/670003E0, prev
3/67000398, desc: DELETE off 4 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/17235/17293 blk 0
rmgr: Transaction len (rec/tot): 34/ 34, tx: 1104338, lsn: 3/67000418, prev
3/670003E0, desc: COMMIT 2022-03-21 18:11:40.389518 JST
WHERE 句がないので
全行 (3 行 )HOT 更新される。

View Slide

実行（ foo の空化）
● ターミナル 2 で、 foo テーブルに対する TRUNCATE を実行する。
backend> TRUNCATE foo
backend>
rmgr: Standby len (rec/tot): 42/ 42, tx: 1104339, lsn: 3/67000440, prev
3/67000418, desc: LOCK xid 1104339 db 17235 rel 17293
3/67000440, desc: NEXTOID 25499
rmgr: Storage len (rec/tot): 42/ 42, tx: 1104339, lsn: 3/67000490, prev
3/67000470, desc: CREATE base/17235/17307
（略）
rmgr: Transaction len (rec/tot): 361/ 361, tx: 1104339, lsn: 3/67005B90, prev
3/67005B00, desc: COMMIT 2022-03-21 18:36:51.568558 JST; rels: base/17235/17297
base/17235/17298 base/17235/17296 base/17235/17293; inval msgs: catcache 51 catcache 50
catcache 51 catcache 50 catcache 51 catcache 50 catcache 51 catcache 50 relcache 17296
relcache 17297 relcache 17297 relcache 17293 relcache 17298 relcache 17298 relcache 17296
relcache 17293
● ！！！（なんかめっさ出力されてる！・・・ 28 行出力された）

View Slide

実行（ foo の空化）
● 一体 TRUNCATE の背景で何が起きているのか。
（ pg_waldump 出力からの推測）
– xid 更新のためのロック , oid の取得
– 17307 （新しい foo relfilenode ）の生成
● カタログっぽい何かの UPDATE/INSERT
– 以下同様にリレーション生成とカタログっぽい何かの UPDATE/INSERT を
繰り返す。時々 Full Page Write もやってる
● foo の toast, foo_pkey, foo_pkey の toast
– 最後に COMMIT
なんか
いろいろやってる

View Slide

実行（ bar への挿入 / 更新 / 削除）
● ターミナル 2 で、 bar テーブルに対する INSERT を実行する。
backend> INSERT INTO bar VALUES (1, 'ABC')
backend> BEGIN
backend> INSERT INTO bar VALUES (2, 'DEF')
backend> INSERT INTO bar VALUES (3, 'XYZ')
backend> COMMIT
backend> BEGIN
backend> UPDATE bar SET data = 'xyz'
backend> DELETE FROM bar WHERE id = 1
backend> COMMIT
backend>
● UNLOGGED TABLE に対する INSERT/UPDATE/DELETE の
COMMIT があっても pg_waldump は何も出力しない。ですよねー

View Slide

実行（ bar の空化）
● ターミナル 2 で、 bar テーブルに対する TRUNCATE を実行する。
backend> TRUNCATE bar
backend>
rmgr: Transaction len (rec/tot): 34/ 34, tx: 1104340, lsn: 3/67005DF0, prev
3/67005D78, desc: COMMIT 2022-03-21 19:08:27.996883 JST
3/67005DF0, desc: COMMIT 2022-03-21 19:09:06.775494 JST
3/67005E18, desc: COMMIT 2022-03-21 19:09:37.835384 JST
rmgr: Standby len (rec/tot): 42/ 42, tx: 1104343, lsn: 3/67005E68, prev
3/67005E40, desc: LOCK xid 1104343 db 17235 rel 17300
（略）
● ！！！（なんかめっさ出力されてる！・・・ 31 行出力された）
UNLOGGED でも
TRUNCATE 処理の WAL は
発生する！

View Slide

実行（ bar の空化）
● だいたい foo の空化と同じだが、その前に 3 つの COMMIT ログも出力されてい
る。
– これは「実行（ bar への挿入 / 更新 / 削除）」スライドで実行していた 3 つ
の UNLOGGED TABLE に対する COMMIT 操作を指しているのだろう
か・・・。
TRUNCATE
なんもわからん

View Slide

わかったこと
● pg_waldump を使うことで、 COMMIT 時に出力される WAL の内容
を見ることができる。
● テーブルにインデックスが張ってあれば、テーブルの更新時に当然、
インデックスも更新されていることが分かる。
● UNLOGGED TABLE への DML 操作＆ COMMIT では WAL 出力はされ
ない。
– TRUNCATE の場合は WAL 出力される。
● TRUNCATE 背景でなんかいろいろ動いている。

View Slide

pg_waldump は何を出力しているのか

View Slide

pg_waldump の出力箇所
● それっぽい場所
– src/bin/pg_waldump/pg_waldump.c
– static void XLogDumpDisplayRecord(XLogDumpConfig
*config, XLogReaderState *record)

View Slide

pg_waldump の出力箇所
● pg_waldump.c の該当箇所ソース抜粋
printf("rmgr: %-11s len (rec/tot): %6u/%6u, tx: %10u, lsn: %X/%08X, prev %X/%08X, ",
desc->rm_name,
rec_len, XLogRecGetTotalLen(record),
XLogRecGetXid(record),
LSN_FORMAT_ARGS(record->ReadRecPtr),
LSN_FORMAT_ARGS(xl_prev));
id = desc->rm_identify(info);
if (id == NULL)
printf("desc: UNKNOWN (%x) ", info & ~XLR_INFO_MASK);
else
printf("desc: %s ", id);
initStringInfo(&s);
desc->rm_desc(&s, record);
printf("%s", s.data);
pfree(s.data);
たぶん
このへんかな

View Slide

実際、何を出力しているのか
● printf の第 2 引数以降 /desc の出力内容
引数内容
desc->rm_name WAL レコードから得られるリソースマネージャ名前
rec_len WAL レコードから XLogDumpRecordLen マクロで得られる WAL レコード
長？
XLogRecGetTotalLen(recor
d)
WAL 総レコード長？
Full Page Write が発生するときは、この値と rec_len の値が異なる？
XLogRecGetXid(record) トランザクション ID
LSN_FORMAT_ARGS(rec
ord->ReadRecPtr)
現在の LSN （ 2 つの値が展開されるマクロ）
LSN_FORMAT_ARGS(xl_
prev)
1 つ前の LSN （ 2 つの値が展開されるマクロ）
desc->rm_desc(&s, record) WAL の内容を示すなんか。

View Slide

pg_waldump 出力例
● pg_waldump の実行例
rmgr: Storage len (rec/tot): 42/ 42, tx: 1104339, lsn: 3/67000490, prev
3/67000470, desc: CREATE base/17235/17307
rmgr: Heap len (rec/tot): 65/ 2469, tx: 1104339, lsn: 3/670004C0, prev
3/67000490, desc: UPDATE off 35 xmax 1104339 flags 0x00 ; new off 5 xmax 0, blkref #0: rel
1663/17235/1259 blk 0 FPW
rmgr: Btree len (rec/tot): 53/ 3373, tx: 1104339, lsn: 3/67000E68, prev
3/670004C0, desc: INSERT_LEAF off 156, blkref #0: rel 1663/17235/2662 blk 2 FPW
リソースマネージャ種別レコード長レコード総長トランザクション ID カレント LSN
1 つ前の LSN WAL レコード内容の説明

View Slide

おまけ： SELECT * FROM WAL

View Slide

ぽすぐれの人の習性
● ぽすぐれの人は何らかのテキストファイルを見つけると、すぐに
FDW 経由で検索しようとする習性がある。【要出典】
● 今のところ、 pg_waldump_fdw は存在しない。たぶん。
– https://wiki.postgresql.org/wiki/Foreign_data_wrappers
● でも大丈夫。 file_fdw があればなんとかなる。
主語でかい

View Slide

file_fdw 経由で pg_waldump 出力をみる
● file_fdw はテキストファイルだけなく、プログラム出力も入力ソースにできる。
● でも、 pg_waldump の出力は CSV や TSV じゃない。
– 固定幅・可変個空白のフォーマットなので、そのままでは file_fdw に適用でき
ない。
● そこで awk ですよ。
– awk でなくても、使い慣れたテキスト処理ツールを使えばよい。

View Slide

CREATE FOREIGN TABLE waldump
(mgr text, kind text, rec int, tot int, tx int, current_lsn pg_lsn, prev pg_lsn, description
text)
SERVER waldump
OPTIONS (
program 'pg_waldump 000000010000000300000067 | gawk ''{printf "%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s
%s %s %s %s %s %s %s %s %s %s %s %s %s %s %s %s\n", substr($1,1,length($1)-1),
$2,substr($5,1,length($5)-1),substr($6,1,length($6)-1),substr($8,1,length($8)-
1),substr($10,1,length($10)-1),substr($12,1,length($12)-1),
$14,$15,$16,$17,$18,$19,$20,$21,$22,$23,$24,$25,$26,$27,$28,$29,$30}'''
)
;
● file_fdw の登録＆外部サーバを定義する
CREATE EXTENSION file_fdw;
CREATE SERVER waldump FOREIGN DATA WRAPPER file_fdw;
かなり
強引
● pg_waldump+awk コマンドを PROGRAM として指定する。

View Slide

● 登録した waldump テーブルの定義。
wal-# \d waldump
Foreign table "public.waldump"
Column | Type | Collation | Nullable | Default | FDW options
-------------+---------+-----------+----------+---------+-------------
mgr | text | | | |
kind | text | | | |
rec | integer | | | |
tot | integer | | | |
tx | integer | | | |
current_lsn | pg_lsn | | | |
prev | pg_lsn | | | |
description | text | | | |
Server: waldump
FDW options: (program E'pg_waldump 000000010000000300000067 | gawk ''{printf "%s\\t%s\\t%s\\t
%s\\t%s\\t%s\\t%s\\t%s %s %s %s %s %s %s %s %s %s %s %s %s %s %s %s %s\\n",
substr($1,1,length($1)-1),$2,substr($5,1,length($5)-1),substr($6,1,length($6)-
1),substr($8,1,length($8)-1),substr($10,1,length($10)-1),substr($12,1,length($12)-1),
$14,$15,$16,$17,$18,$19,$20,$21,$22,$23,$24,$25,$26,$27,$28,$29,$30}''')
wal-#

View Slide

● SELECT の実行例
wal=# SELECT * FROM waldump LIMIT 2;
pg_waldump: fatal: error in WAL record at 3/670878E8: invalid record length at 3/67087920:
wanted 24, got 0
mgr | kind | rec | tot | tx | current_lsn | prev |
description
------+------+-----+-----+----+-------------+------------
+-------------------------------------------------------------------------------------
----------------------------------------------------------------------------------------------
---------------
rmgr | XLOG | 114 | 114 | 0 | 3/67000028 | 0/0 | CHECKPOINT_SHUTDOWN redo
3/67000028; tli 1; prev tli 1; fpw true; xid 0:1104336; oid
17307; multi 1; offset
rmgr | XLOG | 54 | 54 | 0 | 3/670000A0 | 3/67000028 | PARAMETER_CHANGE
max_connections=100 max_worker_processes=8 max_wal_senders=10 max_p
repared_xacts=0 max_locks_per_xact=64 wal_level=replica wal_log_hints=off
track_commit_timestamp=off
(2 rows)
pg_waldump の
fatal は気にしない

View Slide

● SELECT の実行例（射影と選択）
wal=# SELECT kind, description FROM waldump WHERE kind IN ('Transaction','Heap') LIMIT 3;
pg_waldump: fatal: error in WAL record at 3/670878E8: invalid record length at 3/67087920:
wanted 24, got 0
kind | description
-------------+---------------------------------------------------------------------------
Heap | INSERT+INIT off 1 flags 0x00, blkref #0: rel 1663/17235/17293 blk 0
Transaction | COMMIT 2022-03-21 17:48:34.759330 JST
Heap | INSERT off 2 flags 0x00, blkref #0: rel 1663/17235/17293 blk 0
(3 rows)
実用的ではないが
こういうことも
できるよと。

View Slide

おわり

View Slide

View WAL

View WAL

nuko_yokohama

More Decks by nuko_yokohama

Other Decks in Technology

Featured

Transcript