Upgrade to Pro — share decks privately, control downloads, hide ads and more …

View WAL

View WAL

View WAL using pg_waldump

nuko_yokohama

May 31, 2022
Tweet

More Decks by nuko_yokohama

Other Decks in Technology

Transcript

  1. what’s pg_waldump? • PostgreSQL の WAL(Write Ahead Log) を可視化するツール。 (可視化はするが読めるとは言っていない)

    • WAL はバイナリファイルなので、バイナリアンでない人では見るのが大変 • pg_waldump は WAL セグメントファイルを読み、謎の書式で 標準出力に出力してくれる。 • 用途は学習・デバッグ用とのこと。 – 実運用での利用は想定はしていないっぽい。 謎の書式?
  2. $ 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 謎のバイナリ ファイル
  3. $ 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 謎のバイナリ ファイル
  4. • 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; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown (略) pg_waldump 実行例 謎の テキスト文字列
  5. 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
  6. おすすめ:シングルユーザモードで動かす • pg_ctl で PostgreSQL サーバを起動しなくても、直接バックエンドプロ セスを起動する方法がある。 – PostgreSQL サーバを停止させておく。

    – postgres --singule <DB 名 > -D <DB クラスタ Dir > – こうすると単一のバックエンドプロセスのみ起動した状態になる。 • この中で DML も DDL も実行できる $ postgres --single test -D $PGDATA PostgreSQL stand-alone backend 14.2 backend>
  7. 対象とするテーブル • とりあえず、以下の 2 つのテーブルを対象にしてみる。 – foo テーブル , bar

    テーブル( UNLOGGED TABLE ) test=# \d (foo|bar) Unlogged table "public.bar" Column | Type | Collation | Nullable | Default --------+---------+-----------+----------+--------- id | integer | | not null | data | text | | | Indexes: "bar_pkey" PRIMARY KEY, btree (id) Table "public.foo" Column | Type | Collation | Nullable | Default --------+---------+-----------+----------+--------- id | integer | | not null | data | text | | | Indexes: "foo_pkey" PRIMARY KEY, btree (id)
  8. 実行する 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 )に 対して実行してみる。
  9. 実行 (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 rmgr: XLOG len (rec/tot): 114/ 114, tx: 0, lsn: 3/67000028, prev 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; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
  10. 実行(バックエンド起動) • ターミナル 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 に記録するっぽい。しらんけど。
  11. 実行( 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 rmgr: Btree len (rec/tot): 64/ 64, tx: 1104336, lsn: 3/67000178, prev 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
  12. 実行( 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 に対する なんかが行われたことがわかる。
  13. 実行( 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 rmgr: Btree len (rec/tot): 64/ 64, tx: 1104337, lsn: 3/67000220, prev 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
  14. 実行( foo への更新と削除) • ターミナル 2 で、 foo テーブルに対する BEGIN/INSERT/COMMIT

    を実行する。 backend> BEGIN backend> UPDATE foo SET data = 'xyz' backend> DELETE FROM foo WHERE id = 1 backend> COMMIT rmgr: Heap len (rec/tot): 71/ 71, tx: 1104338, lsn: 3/67000308, prev 3/670002E0, desc: HOT_UPDATE off 1 xmax 1104338 flags 0x20 ; new off 4 xmax 0, blkref #0: rel 1663/17235/17293 blk 0 rmgr: Heap len (rec/tot): 71/ 71, tx: 1104338, lsn: 3/67000350, prev 3/67000308, desc: HOT_UPDATE off 2 xmax 1104338 flags 0x20 ; new off 5 xmax 0, blkref #0: rel 1663/17235/17293 blk 0 rmgr: Heap len (rec/tot): 71/ 71, tx: 1104338, lsn: 3/67000398, prev 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 更新される。
  15. 実行( 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 rmgr: XLOG len (rec/tot): 30/ 30, tx: 1104339, lsn: 3/67000470, prev 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 行出力された)
  16. 実行( foo の空化) • 一体 TRUNCATE の背景で何が起きているのか。 ( pg_waldump 出力からの推測)

    – xid 更新のためのロック , oid の取得 – 17307 (新しい foo relfilenode )の生成 • カタログっぽい何かの UPDATE/INSERT – 以下同様にリレーション生成とカタログっぽい何かの UPDATE/INSERT を 繰り返す。時々 Full Page Write もやってる • foo の toast, foo_pkey, foo_pkey の toast – 最後に COMMIT なんか いろいろやってる
  17. 実行( 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 は何も出力しない。 ですよねー
  18. 実行( 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 rmgr: Transaction len (rec/tot): 34/ 34, tx: 1104341, lsn: 3/67005E18, prev 3/67005DF0, desc: COMMIT 2022-03-21 19:09:06.775494 JST rmgr: Transaction len (rec/tot): 34/ 34, tx: 1104342, lsn: 3/67005E40, prev 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 は 発生する!
  19. 実行( bar の空化) • だいたい foo の空化と同じだが、その前に 3 つの COMMIT

    ログも出力されてい る。 – これは「実行( bar への挿入 / 更新 / 削除)」スライドで実行していた 3 つ の UNLOGGED TABLE に対する COMMIT 操作を指しているのだろう か・・・。 TRUNCATE なんもわからん
  20. わかったこと • pg_waldump を使うことで、 COMMIT 時に出力される WAL の内容 を見ることができる。 •

    テーブルにインデックスが張ってあれば、テーブルの更新時に当然、 インデックスも更新されていることが分かる。 • UNLOGGED TABLE への DML 操作& COMMIT では WAL 出力はされ ない。 – TRUNCATE の場合は WAL 出力される。 • TRUNCATE 背景でなんかいろいろ動いている。
  21. 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); たぶん このへんかな
  22. 実際、何を出力しているのか • 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 の内容を示すなんか。
  23. 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 レコード内容の説明
  24. file_fdw 経由で pg_waldump 出力をみる • file_fdw はテキストファイルだけなく、プログラム出力も入力ソースにできる。 • でも、 pg_waldump

    の出力は CSV や TSV じゃない。 – 固定幅・可変個空白のフォーマットなので、そのままでは file_fdw に適用でき ない。 • そこで awk ですよ。 – awk でなくても、使い慣れたテキスト処理ツールを使えばよい。
  25. 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 経由で pg_waldump 出力をみる • file_fdw の登録&外部サーバを定義する CREATE EXTENSION file_fdw; CREATE SERVER waldump FOREIGN DATA WRAPPER file_fdw; かなり 強引 • pg_waldump+awk コマンドを PROGRAM として指定する。
  26. file_fdw 経由で pg_waldump 出力をみる • 登録した 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-#
  27. file_fdw 経由で pg_waldump 出力をみる • 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 は気にしない
  28. file_fdw 経由で pg_waldump 出力をみる • 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) 実用的ではないが こういうことも できるよと。