最近、pg_waldumpの出力結果の読み方を聞かれる機会があったものの、ここをみればとりあえずOK。と言えそうなサイトがすぐに出てこなかったので、ここにメモを残しておきます。
##pg_waldumpとは
マニュアルによると「pg_waldump — PostgreSQLデータベースクラスタの先行書き込みログ(=WAL)を可読性が高い表現で表示する」となっています。参照元はここです。
PostgreSQL 8.Xのころは「xlogdump」、9.Xでは「pg_xlogdump」など、名前は変えつつもなんだかんだ長く使われている優良ツールだと思います。
が、出力結果はテキストに変換されて人が読める形にはなるけど、WALがどんな物かを理解してないと決して見やすくはない感じです｡
自分もそんなにちゃんと理解してるわけではないんですがね。
##前準備(WALの準備)
pg_waldumpはWALを読むツールなので、読取り対象となるWALが存在している必要があります。
今回は下記のやり方で用意しました。
[postgres@localhost data]$ pg_ctl --version
pg_ctl (PostgreSQL) 11.4
[postgres@localhost data]$ echo $PGDATA
/var/lib/pgsql/11/data
[postgres@localhost data]$ pg_ctl init
データベースシステム内のファイルの所有者は"postgres"となります。
このユーザがサーバプロセスも所有する必要があります。
(中略)
成功しました。以下のようにしてデータベースサーバを起動できます。
/usr/pgsql-11/bin/pg_ctl -D /var/lib/pgsql/11/data -l <ログファイル> start
[postgres@localhost data]$ pg_ctl start
サーバの起動完了を待っています....2019-07-02 22:00:15.617 JST [9748] LOG: IPv6アドレス"::1"、ポート5432で待ち受けています
2019-07-02 22:00:15.618 JST [9748] LOG: IPv4アドレス"127.0.0.1"、ポート5432で待ち受けています
2019-07-02 22:00:15.620 JST [9748] LOG: Unixソケット"/var/run/postgresql/.s.PGSQL.5432"で待ち受けています
2019-07-02 22:00:15.624 JST [9748] LOG: Unixソケット"/tmp/.s.PGSQL.5432"で待ち受けています
2019-07-02 22:00:15.678 JST [9748] LOG: ログ出力をログ収集プロセスにリダイレクトしています
2019-07-02 22:00:15.678 JST [9748] ヒント: ここからのログ出力はディレクトリ"log"に現れます。
完了
サーバ起動完了
[postgres@localhost data]$ psql
psql (11.4)
"help" でヘルプを表示します。
postgres=# create table test (c1 int);
CREATE TABLE
postgres=# insert into test values(1);
INSERT 0 1
postgres=# insert into test values(2);
INSERT 0 1
postgres=# select xmin,* from test;
xmin | c1
------+----
569 | 1
570 | 2
(2 行)
postgres=# \q
ここまでで、xid(=xmin)が569と570でINSERTされた行が2つできました。
次に手っ取り早くWALをファイルに書き出す為に postgres を再起動します。
[postgres@localhost data]$ pg_ctl restart
サーバ停止処理の完了を待っています....完了
サーバは停止しました
サーバの起動完了を待っています....2019-07-02 22:01:37.624 JST [9841] LOG: IPv6アドレス"::1"、ポート5432で待ち受けています
2019-07-02 22:01:37.624 JST [9841] LOG: IPv4アドレス"127.0.0.1"、ポート5432で待ち受けています
2019-07-02 22:01:37.627 JST [9841] LOG: Unixソケット"/var/run/postgresql/.s.PGSQL.5432"で待ち受けています
2019-07-02 22:01:37.631 JST [9841] LOG: Unixソケット"/tmp/.s.PGSQL.5432"で待ち受けています
2019-07-02 22:01:37.689 JST [9841] LOG: ログ出力をログ収集プロセスにリダイレクトしています
2019-07-02 22:01:37.689 JST [9841] ヒント: ここからのログ出力はディレクトリ"log"に現れます。
完了
サーバ起動完了
[postgres@localhost data]$ ls -lrt $PGDATA/pg_wal
合計 16384
drwx------ 2 postgres postgres 6 7月 2 22:00 archive_status
-rw------- 1 postgres postgres 16777216 7月 2 22:01 000000010000000000000001
[postgres@localhost data]$
##pg_waldump実行
下記のように実行して、WALの内容を表示します。
「--rmgr: Heap」をしていしているのは、テーブルやインデックスをのを更新するのはHeapリソースマネージャの役目なので、出力結果をHeapだけに絞るためです。(今回みたいな場合は「-x xid」でもよかったかも)
下記は先程の2件のINSERTに関する行のみ表示しています。これは「xt:」の後に表示されるトランザクションIDと、先程のINSERTの結果挿入された行のxmin列の対応関係で判断します。
[postgres@localhost pg_wal]$ cd $PGDATA/pg_wal
[postgres@localhost pg_wal]$ pg_waldump 000000010000000000000001 --rmgr=Heap
(中略)
rmgr: Heap len (rec/tot): 59/ 59, tx: 569, lsn: 0/016C8798, prev 0/016C8600, desc: INSERT+INIT off 1, blkref #0: rel 1663/13878/16384 blk 0
rmgr: Heap len (rec/tot): 59/ 59, tx: 570, lsn: 0/016C8800, prev 0/016C87D8, desc: INSERT off 2, blkref #0: rel 1663/13878/16384 blk 0
処理の内容は「desc:」の所で表示されます。今回はINSERTの処理なので「INAERT」や「INSERT+INIT」になります。
「INSERT+INIT」は初回INSERT時のように領域の初期化を伴う場合に出力されます。
じゃあどのテーブルにINSERTしたのかというのは「rel」の所で確認します。
上記の例では「1663/13878/16384」と表示されていますが、これは
「テーブルスペースのOID/データベースのOID/テーブルのOID」という形式で表現されています。
各OIDは「oid2name」コマンドで確認できます。
######テーブルスペースのOID
[postgres@localhost ~]$ oid2name -s
All tablespaces:
Oid Tablespace Name
-----------------------
1663 pg_default
1664 pg_global
######データベースのOID
[postgres@localhost ~]$ oid2name
All databases:
Oid Database Name Tablespace
----------------------------------
13878 postgres pg_default
13877 template0 pg_default
1 template1 pg_default
######テーブルのOID
[postgres@localhost ~]$ oid2name -d postgres
From database "postgres":
Filenode Table Name
----------------------
16384 test
一瞬「あ、テーブル名を表示するオプションとか用意したら便利じゃね？」とは思いましたが、きっと敢えてそうしてない理由が何かあるんだろうな｡｡｡