In this blog, we will see the concepts for analyzing WAL files, such as pg_waldump (supported versions 12 and above) and pg_walinspect (supported versions 15 and above).
Write-Ahead Logging (WAL) is a standard approach to transaction logging and one of the database’s functional components.
The utility pg_waldump demonstrates human-readable information from the WAL file segments.
Below, we demonstrate how to use pg_waldump using the WAL function pg_current_wal_lsn (last write location).
As a first step, we will capture the current pg_lsn to analyze the details of the WAL.
|
1 |
wal_db=# SELECT pg_current_wal_lsn(), pg_walfile_name( pg_current_wal_lsn() );;<br>pg_current_wal_lsn | pg_walfile_name <br>--------------------+--------------------------<br>0/1969628 | 000000010000000000000001<br>(1 row) |
Next, we will perform a few SQL operations to analyze them in the WAL file.
|
1 |
wal_db=# CREATE TABLE region (<br> region_id smallint NOT NULL,<br> region_description character varying(60) NOT NULL<br>);<br>CREATE TABLE<br><br>wal_db=# INSERT INTO region VALUES (1, 'Eastern');<br>INSERT INTO region VALUES (2, 'Western');<br>INSERT INTO region VALUES (3, 'Northern');<br>INSERT INTO region VALUES (4, 'Southern');<br>INSERT 0 1<br>INSERT 0 1<br>INSERT 0 1<br>INSERT 0 1<br><br>wal_db=# ALTER TABLE ONLY region<br> ADD CONSTRAINT pk_region PRIMARY KEY (region_id);<br>ALTER TABLE<br><br>wal_db=# UPDATE region SET region_description = 'Southern Region' where region_id=4;<br>UPDATE 1<br><br>wal_db=# DELETE FROM region where region_id=3;<br>DELETE 1 |
Lastly, we will capture the current pg_lsn to analyze the details of the WAL.
|
1 |
wal_db=# SELECT pg_current_wal_lsn(), pg_walfile_name( pg_current_wal_lsn() );;<br>pg_current_wal_lsn | pg_walfile_name <br>--------------------+--------------------------<br>0/197FA00 | 000000010000000000000001<br>(1 row) |
We will use the utility pg_waldump and try to read the SQL from the WAL file.
|
1 |
[postgres@ip-****** ~]$ /usr/pgsql-14/bin/pg_waldump -s 0/1702AB0 -e 0/17304C0 -p /var/lib/pgsql/14/data/pg_wal/ 000000010000000000000001 |
As per the sequence of operations, initially in Waldump, we can see CREATE, through which object(table: region) is created in base/16388/16390, and then the COMMIT transaction is performed.
|
1 |
wal_db=# select oid,relname,relkind from pg_class where oid='16390';<br> oid | relname | relkind <br>-------+---------+---------<br> 16390 | region | r<br>(1 row) |
|
1 |
rmgr: Storage len (rec/tot): 42/ 42, tx: 0, lsn: 0/01969628, prev 0/019695F0, desc: CREATE base/16388/16390<br>rmgr: Heap len (rec/tot): 211/ 211, tx: 737, lsn: 0/01969658, prev 0/01969628, desc: INSERT off 10 flags 0x01, blkref #0: rel 1663/16388/1247 blk 14<br>rmgr: Btree len (rec/tot): 64/ 64, tx: 737, lsn: 0/01969730, prev 0/01969658, desc: INSERT_LEAF off 246, blkref #0: rel 1663/16388/2703 blk 2<br>…………………..<br>rmgr: Standby len (rec/tot): 42/ 42, tx: 737, lsn: 0/0196A640, prev 0/0196A5F8, desc: LOCK xid 737 db 16388 rel 16390 <br>rmgr: Transaction len (rec/tot): 437/ 437, tx: 737, lsn: 0/0196A670, prev 0/0196A640, desc: COMMIT 2024-06-21 22:05:41.105061 UTC; inval msgs: catcache 80 catcache 79 catcache 80 catcache 79 catcache 55 catcache 54 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 catcache 7 catcache 6 snapshot 2608 relcache 16390 |
|
1 |
rmgr: Standby len (rec/tot): 54/ 54, tx: 0, lsn: 0/0196A828, prev 0/0196A670, desc: RUNNING_XACTS nextXid 739 latestCompletedXid 737 oldestRunningXid 738; 1 xacts: 738<br>rmgr: Heap len (rec/tot): 65/ 65, tx: 738, lsn: 0/0196A860, prev 0/0196A828, desc: INSERT+INIT off 1 flags 0x00, blkref #0: rel 1663/16388/16390 blk 0<br>rmgr: Transaction len (rec/tot): 34/ 34, tx: 738, lsn: 0/0196A8A8, prev 0/0196A860, desc: COMMIT 2024-06-21 22:05:46.935316 UTC<br>rmgr: Heap len (rec/tot): 65/ 65, tx: 739, lsn: 0/0196A8D0, prev 0/0196A8A8, desc: INSERT off 2 flags 0x00, blkref #0: rel 1663/16388/16390 blk 0<br>rmgr: Transaction len (rec/tot): 34/ 34, tx: 739, lsn: 0/0196A918, prev 0/0196A8D0, desc: COMMIT 2024-06-21 22:05:46.937898 UTC<br>rmgr: Heap len (rec/tot): 66/ 66, tx: 740, lsn: 0/0196A940, prev 0/0196A918, desc: INSERT off 3 flags 0x00, blkref #0: rel 1663/16388/16390 blk 0<br>rmgr: Transaction len (rec/tot): 34/ 34, tx: 740, lsn: 0/0196A988, prev 0/0196A940, desc: COMMIT 2024-06-21 22:05:46.938915 UTC<br>rmgr: Heap len (rec/tot): 66/ 66, tx: 741, lsn: 0/0196A9B0, prev 0/0196A988, desc: INSERT off 4 flags 0x00, blkref #0: rel 1663/16388/16390 blk 0<br>rmgr: Transaction len (rec/tot): 34/ 34, tx: 741, lsn: 0/0196A9F8, prev 0/0196A9B0, desc: COMMIT 2024-06-21 22:05:46.939988 UTC |
Next, after COMMIT and for the ALTER operation performed as in the example, CREATE INDEX(pk_region) is performed, and then COMMIT of a transaction is performed.
|
1 |
wal_db=# select oid,relname,relkind from pg_class where oid='16393';<br> oid | relname | relkind <br>-------+-----------+---------<br> 16393 | pk_region | i<br>(1 row) |
|
1 |
rmgr: Standby len (rec/tot): 42/ 42, tx: 742, lsn: 0/0196AA20, prev 0/0196A9F8, desc: LOCK xid 742 db 16388 rel 16390 <br>rmgr: Storage len (rec/tot): 42/ 42, tx: 742, lsn: 0/0196AA50, prev 0/0196AA20, desc: CREATE base/16388/16393<br>rmgr: Standby len (rec/tot): 42/ 42, tx: 742, lsn: 0/0196AA80, prev 0/0196AA50, desc: LOCK xid 742 db 16388 rel 16393 <br>rmgr: Heap len (rec/tot): 54/ 1050, tx: 742, lsn: 0/0196AAB0, prev 0/0196AA80, desc: INSERT off 3 flags 0x00, blkref #0: rel 1663/16388/1259 blk 0 FPW<br>……………………………<br>rmgr: XLOG len (rec/tot): 49/ 137, tx: 742, lsn: 0/0197F5B0, prev 0/0197F500, desc: FPI , blkref #0: rel 1663/16388/16393 blk 0 FPW<br>rmgr: Heap len (rec/tot): 188/ 188, tx: 742, lsn: 0/0197F640, prev 0/0197F5B0, desc: INPLACE off 2, blkref #0: rel 1663/16388/1259 blk 0<br>rmgr: Heap len (rec/tot): 188/ 188, tx: 742, lsn: 0/0197F700, prev 0/0197F640, desc: INPLACE off 3, blkref #0: rel 1663/16388/1259 blk 0<br>rmgr: Transaction len (rec/tot): 293/ 293, tx: 742, lsn: 0/0197F7C0, prev 0/0197F700, desc: COMMIT 2024-06-21 22:05:52.409013 UTC; inval msgs: catcache 55 catcache 54 catcache 7 catcache 6 catcache 32 catcache 19 catcache 55 catcache 54 catcache 55 catcache 54 relcache 16393 relcache 16390 snapshot 2608 relcache 16390 relcache 16393 |
Later, after COMMIT, and for the UPDATE operation performed, as in the example, HOT_UPDATE is performed, and then COMMIT of a transaction is performed.
|
1 |
rmgr: Heap len (rec/tot): 84/ 84, tx: 743, lsn: 0/0197F8E8, prev 0/0197F7C0, desc: HOT_UPDATE off 4 xmax 743 flags 0x00 ; new off 5 xmax 0, blkref #0: rel 1663/16388/16390 blk 0<br>rmgr: Transaction len (rec/tot): 34/ 34, tx: 743, lsn: 0/0197F940, prev 0/0197F8E8, desc: COMMIT 2024-06-21 22:05:57.693419 UTC |
Lastly, after performing the COMMIT and DELETE operations as in the example, you can see the DELETE, Transaction COMMIT, and then snapshot through RUNNING_XACTS.
|
1 |
rmgr: Heap len (rec/tot): 54/ 54, tx: 744, lsn: 0/0197F968, prev 0/0197F940, desc: DELETE off 3 flags 0x00 KEYS_UPDATED , blkref #0: rel 1663/16388/16390 blk 0<br>rmgr: Transaction len (rec/tot): 34/ 34, tx: 744, lsn: 0/0197F9A0, prev 0/0197F968, desc: COMMIT 2024-06-21 22:06:02.838984 UTC<br>rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn: 0/0197F9C8, prev 0/0197F9A0, desc: RUNNING_XACTS nextXid 745 latestCompletedXid 744 oldestRunningXid 745 |
In current supported PG versions 12.x and above, developers have implemented pg_waldump for usage, and they have created a new feature, pg_walinspect, for debugging WALs in detail using SQL from version 15.x onwards.
pg_walinspect module provides SQL functions for inspecting and debugging WALs that are accessible through SQL rather than a separate utility.
|
1 |
wal_db=# CREATE EXTENSION pg_walinspect ;<br>CREATE EXTENSION<br><br>wal_db=# dx pg_walinspect<br> List of installed extensions<br> Name | Version | Schema | Description <br>---------------+---------+--------+-------------------------------------------------------------<br>pg_walinspect | 1.0 | public | functions to inspect contents of PostgreSQL Write-Ahead Log<br>(1 row) |
Below is the usage of pg_walinspect, where we use functions to demonstrate the operations through WALs and can check the resource_manager, record_type, and description columns specifically for analysis.
Below, we inspect the WAL using the same SQL commands executed for pg_waldump.
|
1 |
<span style="font-weight: 400;">wal_db=# select start_lsn, end_lsn, xid, resource_manager, record_type, record_length, description::varchar(50) from pg_get_wal_records_info('0/1A1E990','0/1A37240');</span> |
Initially, we can see CREATE through which object is created in base/16388/16410 and then COMMIT.
|
1 |
start_lsn | end_lsn | xid | resource_manager | record_type | record_length | description <br>-----------+-----------+-----+------------------+---------------+---------------+----------------<br>0/1A1E990 | 0/1A1E9C0 | 0 | Storage | CREATE | 42 | base/16388/16410<br>0/1A1E9C0 | 0/1A1EA98 | 753 | Heap | INSERT | 211 | off 14 flags 0x00<br>0/1A1EA98 | 0/1A1FE80 | 753 | Btree | INSERT_LEAF | 5093 | off 250<br>…………………………….<br>0/1A300F0 | 0/1A30120 | 753 | Standby | LOCK | 42 | xid 753 db 16388 rel 16410 <br>0/1A30120 | 0/1A302D8 | 753 | Transaction | COMMIT | 437 | 2024-06-21 23:51:56.058043+00; inval msgs: catcach |
Secondly, after COMMIT, a snapshot is taken through RUNNING_XACTS and INSERT and then COMMIT.
|
1 |
start_lsn | end_lsn | xid | resource_manager | record_type | record_length | description <br>-----------+-----------+-----+------------------+---------------+---------------+----------------<br>0/1A302D8 | 0/1A30310 | 0 | Standby | RUNNING_XACTS | 50 | nextXid 754 latestCompletedXid 753 oldestRunningXi<br>0/1A30310 | 0/1A30358 | 754 | Heap | INSERT+INIT | 65 | off 1 flags 0x00<br>0/1A30358 | 0/1A30380 | 754 | Transaction | COMMIT | 34 | 2024-06-21 23:52:07.201926+00<br>0/1A30380 | 0/1A303C8 | 755 | Heap | INSERT | 65 | off 2 flags 0x00<br>0/1A303C8 | 0/1A303F0 | 755 | Transaction | COMMIT | 34 | 2024-06-21 23:52:07.203001+00<br>0/1A303F0 | 0/1A30438 | 756 | Heap | INSERT | 66 | off 3 flags 0x00<br>0/1A30438 | 0/1A30460 | 756 | Transaction | COMMIT | 34 | 2024-06-21 23:52:07.20389+00<br>0/1A30460 | 0/1A304A8 | 757 | Heap | INSERT | 66 | off 4 flags 0x00<br>0/1A304A8 | 0/1A304D0 | 757 | Transaction | COMMIT | 34 | 2024-06-21 23:52:07.204949+00 |
Next, after COMMIT and ALTER operation performed as in the example, we see CREATE INDEX followed by COMMIT.
|
1 |
start_lsn | end_lsn | xid | resource_manager | record_type | record_length | description <br>-----------+-----------+-----+------------------+---------------+---------------+----------------<br>0/1A304D0 | 0/1A30500 | 758 | Standby | LOCK | 42 | xid 758 db 16388 rel 16410 <br>0/1A30500 | 0/1A30530 | 758 | Storage | CREATE | 42 | base/16388/16413<br>0/1A30530 | 0/1A30560 | 758 | Standby | LOCK | 42 | xid 758 db 16388 rel 16413 <br>0/1A30560 | 0/1A30630 | 758 | Heap | INSERT | 203 | off 5 flags 0x00<br>0/1A30630 | 0/1A30670 | 758 | Btree | INSERT_LEAF | 64 | off 120<br>0/1A30670 | 0/1A306B8 | 758 | Btree | INSERT_LEAF | 72 | off 89<br>………………<br>0/1A37000 | 0/1A37128 | 758 | Transaction | COMMIT | 293 | 2024-06-21 23:52:11.627248+00; inval msgs: catcach |
Later, after COMMIT, for the UPDATE operation, HOT_UPDATE is performed, and then COMMIT.
|
1 |
start_lsn | end_lsn | xid | resource_manager | record_type | record_length | description <br>-----------+-----------+-----+------------------+---------------+---------------+---------------<br>0/1A37128 | 0/1A37160 | 0 | Standby | RUNNING_XACTS | 50 | nextXid 759 latestCompletedXid 758 oldestRunningXi<br>0/1A37160 | 0/1A371B8 | 759 | Heap | HOT_UPDATE | 84 | off 4 xmax 759 flags 0x00 ; new off 5 xmax 0<br>0/1A371B8 | 0/1A371E0 | 759 | Transaction | COMMIT | 34 | 2024-06-21 23:52:16.396121+00 |
Lastly, after COMMIT, for the DELETE operation, we can see a DELETE record followed by COMMIT.
|
1 |
start_lsn | end_lsn | xid | resource_manager | record_type | record_length | description <br>-----------+-----------+-----+------------------+---------------+---------------+---------------<br>0/1A371E0 | 0/1A37218 | 760 | Heap | DELETE | 54 | off 3 flags 0x00 KEYS_UPDATED <br>0/1A37218 | 0/1A37240 | 760 | Transaction | COMMIT | 34 | 2024-06-21 23:52:20.17473+00<br>(86 rows) |
Here we will see the access needed for the user to execute the functions for pg_walinspect.
pg_walinspect can be used by the user who has been granted the role ‘pg_read_server_files‘.
|
1 |
wal_db=> select start_lsn, end_lsn, xid, resource_manager, record_type, record_length, description::varchar(50) from pg_get_wal_records_info('0/1A1E990','0/1A37240'); |
ERROR: permission denied for function pg_get_wal_records_info.
Now, we will grant access to ‘pg_read_server_files’ to the role.
|
1 |
GRANT pg_read_server_files to wal_user; |
Now user ‘wal_user’ should be able to access the functions.
|
1 |
[postgres@ip-****** extension]$ psql -p 5433 -d wal_db -U wal_user -h localhost<br>Password for user wal_user: <br>psql (15.7)<br>Type "help" for help.<br><br>wal_db=> select start_lsn, end_lsn, xid, resource_manager, record_type, record_length, description::varchar(50) from pg_get_wal_records_info('0/1A1E990','0/1A37240') limit 2;<br> start_lsn | end_lsn | xid | resource_manager | record_type | record_length | description <br>-----------+-----------+-----+------------------+-------------+---------------+-------------------<br>0/1A1E990 | 0/1A1E9C0 | 0 | Storage | CREATE | 42 | base/16388/16410<br>0/1A1E9C0 | 0/1A1EA98 | 753 | Heap | INSERT | 211 | off 14 flags 0x00<br>(2 rows) |
We have reviewed the usage and analysis of WAL files using the pg_waldump utility and the pg_walinspect extension. Additionally, you can review a few related blogs on WAL in PostgreSQL:
Our PostgreSQL Performance Tuning eBook condenses years of database expertise into a practical guide for optimizing your PostgreSQL databases. Inside, you’ll discover our most effective PostgreSQL performance strategies derived from real-world experience.