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.
- WAL is a standard method for ensuring data durability. It records changes to the database before flushing the actual data to datafiles or rel files, helping recover the database to a consistent state in case of failure.
- The primary benefit of using WAL is that it is ACID-compliant, ensuring Durability. It also significantly reduces the number of writes and supports online backup and point-in-time restore.
- WAL saves the entire data page content (Full Page Write) in the log if necessary to prevent Torn Pages and ensure consistency of the starting page for any recovery.
pg_waldump
The utility pg_waldump demonstrates human-readable information from the WAL file segments.
Requirements
- Set wal_level to ‘replica’ or higher to access the WAL functions, and on RDS, set wal_level to ‘logical’ to execute the WAL functions.
- The user who installed the server or who has read access to the data directory can only use pg_waldump.
Usage and demonstration of pg_waldump
- pg_waldump -p [path to wal files] -s <start LSN> -e [end LSN] [walfile]
- pg_waldump -p [path to wal files] <wal file>
- pg_waldump <walfile> -q
-q, –quiet : do not print any output, except for errors
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 2 3 4 5 | wal_db=# SELECT pg_current_wal_lsn(), pg_walfile_name( pg_current_wal_lsn() );; pg_current_wal_lsn | pg_walfile_name --------------------+-------------------------- 0/1969628 | 000000010000000000000001 (1 row) |
Next, we will perform a few SQL operations to analyze them in the WAL file.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 | wal_db=# CREATE TABLE region ( region_id smallint NOT NULL, region_description character varying(60) NOT NULL ); CREATE TABLE wal_db=# INSERT INTO region VALUES (1, 'Eastern'); INSERT INTO region VALUES (2, 'Western'); INSERT INTO region VALUES (3, 'Northern'); INSERT INTO region VALUES (4, 'Southern'); INSERT 0 1 INSERT 0 1 INSERT 0 1 INSERT 0 1 wal_db=# ALTER TABLE ONLY region ADD CONSTRAINT pk_region PRIMARY KEY (region_id); ALTER TABLE wal_db=# UPDATE region SET region_description = 'Southern Region' where region_id=4; UPDATE 1 wal_db=# DELETE FROM region where region_id=3; DELETE 1 |
Lastly, we will capture the current pg_lsn to analyze the details of the WAL.
1 2 3 4 5 | wal_db=# SELECT pg_current_wal_lsn(), pg_walfile_name( pg_current_wal_lsn() );; pg_current_wal_lsn | pg_walfile_name --------------------+-------------------------- 0/197FA00 | 000000010000000000000001 (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 2 3 4 5 | wal_db=# select oid,relname,relkind from pg_class where oid='16390'; oid | relname | relkind -------+---------+--------- 16390 | region | r (1 row) |
1 2 3 4 5 6 | rmgr: Storage len (rec/tot): 42/ 42, tx: 0, lsn: 0/01969628, prev 0/019695F0, desc: CREATE base/16388/16390 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 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 ………………….. rmgr: Standby len (rec/tot): 42/ 42, tx: 737, lsn: 0/0196A640, prev 0/0196A5F8, desc: LOCK xid 737 db 16388 rel 16390 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 2 3 4 5 6 7 8 9 | 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 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 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 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 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 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 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 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 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 2 3 4 5 | wal_db=# select oid,relname,relkind from pg_class where oid='16393'; oid | relname | relkind -------+-----------+--------- 16393 | pk_region | i (1 row) |
1 2 3 4 5 6 7 8 9 | rmgr: Standby len (rec/tot): 42/ 42, tx: 742, lsn: 0/0196AA20, prev 0/0196A9F8, desc: LOCK xid 742 db 16388 rel 16390 rmgr: Storage len (rec/tot): 42/ 42, tx: 742, lsn: 0/0196AA50, prev 0/0196AA20, desc: CREATE base/16388/16393 rmgr: Standby len (rec/tot): 42/ 42, tx: 742, lsn: 0/0196AA80, prev 0/0196AA50, desc: LOCK xid 742 db 16388 rel 16393 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 …………………………… 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 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 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 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 2 | 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 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 2 3 | 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 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 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
pg_walinspect module provides SQL functions for inspecting and debugging WALs that are accessible through SQL rather than a separate utility.
Installation of pg_walinspect
1 2 3 4 5 6 7 8 9 | wal_db=# CREATE EXTENSION pg_walinspect ; CREATE EXTENSION wal_db=# dx pg_walinspect List of installed extensions Name | Version | Schema | Description ---------------+---------+--------+------------------------------------------------------------- pg_walinspect | 1.0 | public | functions to inspect contents of PostgreSQL Write-Ahead Log (1 row) |
Usage and demonstration of pg_walinspect
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 2 3 4 5 6 7 8 | start_lsn | end_lsn | xid | resource_manager | record_type | record_length | description -----------+-----------+-----+------------------+---------------+---------------+---------------- 0/1A1E990 | 0/1A1E9C0 | 0 | Storage | CREATE | 42 | base/16388/16410 0/1A1E9C0 | 0/1A1EA98 | 753 | Heap | INSERT | 211 | off 14 flags 0x00 0/1A1EA98 | 0/1A1FE80 | 753 | Btree | INSERT_LEAF | 5093 | off 250 ……………………………. 0/1A300F0 | 0/1A30120 | 753 | Standby | LOCK | 42 | xid 753 db 16388 rel 16410 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 2 3 4 5 6 7 8 9 10 11 | start_lsn | end_lsn | xid | resource_manager | record_type | record_length | description -----------+-----------+-----+------------------+---------------+---------------+---------------- 0/1A302D8 | 0/1A30310 | 0 | Standby | RUNNING_XACTS | 50 | nextXid 754 latestCompletedXid 753 oldestRunningXi 0/1A30310 | 0/1A30358 | 754 | Heap | INSERT+INIT | 65 | off 1 flags 0x00 0/1A30358 | 0/1A30380 | 754 | Transaction | COMMIT | 34 | 2024-06-21 23:52:07.201926+00 0/1A30380 | 0/1A303C8 | 755 | Heap | INSERT | 65 | off 2 flags 0x00 0/1A303C8 | 0/1A303F0 | 755 | Transaction | COMMIT | 34 | 2024-06-21 23:52:07.203001+00 0/1A303F0 | 0/1A30438 | 756 | Heap | INSERT | 66 | off 3 flags 0x00 0/1A30438 | 0/1A30460 | 756 | Transaction | COMMIT | 34 | 2024-06-21 23:52:07.20389+00 0/1A30460 | 0/1A304A8 | 757 | Heap | INSERT | 66 | off 4 flags 0x00 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 2 3 4 5 6 7 8 9 10 | start_lsn | end_lsn | xid | resource_manager | record_type | record_length | description -----------+-----------+-----+------------------+---------------+---------------+---------------- 0/1A304D0 | 0/1A30500 | 758 | Standby | LOCK | 42 | xid 758 db 16388 rel 16410 0/1A30500 | 0/1A30530 | 758 | Storage | CREATE | 42 | base/16388/16413 0/1A30530 | 0/1A30560 | 758 | Standby | LOCK | 42 | xid 758 db 16388 rel 16413 0/1A30560 | 0/1A30630 | 758 | Heap | INSERT | 203 | off 5 flags 0x00 0/1A30630 | 0/1A30670 | 758 | Btree | INSERT_LEAF | 64 | off 120 0/1A30670 | 0/1A306B8 | 758 | Btree | INSERT_LEAF | 72 | off 89 ……………… 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 2 3 4 5 | start_lsn | end_lsn | xid | resource_manager | record_type | record_length | description -----------+-----------+-----+------------------+---------------+---------------+--------------- 0/1A37128 | 0/1A37160 | 0 | Standby | RUNNING_XACTS | 50 | nextXid 759 latestCompletedXid 758 oldestRunningXi 0/1A37160 | 0/1A371B8 | 759 | Heap | HOT_UPDATE | 84 | off 4 xmax 759 flags 0x00 ; new off 5 xmax 0 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 2 3 4 5 | start_lsn | end_lsn | xid | resource_manager | record_type | record_length | description -----------+-----------+-----+------------------+---------------+---------------+--------------- 0/1A371E0 | 0/1A37218 | 760 | Heap | DELETE | 54 | off 3 flags 0x00 KEYS_UPDATED 0/1A37218 | 0/1A37240 | 760 | Transaction | COMMIT | 34 | 2024-06-21 23:52:20.17473+00 (86 rows) |
Access and Illustration for using pg_walinspect
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 2 3 4 5 6 7 8 9 10 11 | [postgres@ip-****** extension]$ psql -p 5433 -d wal_db -U wal_user -h localhost Password for user wal_user: psql (15.7) Type "help" for help. 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; start_lsn | end_lsn | xid | resource_manager | record_type | record_length | description -----------+-----------+-----+------------------+-------------+---------------+------------------- 0/1A1E990 | 0/1A1E9C0 | 0 | Storage | CREATE | 42 | base/16388/16410 0/1A1E9C0 | 0/1A1EA98 | 753 | Heap | INSERT | 211 | off 14 flags 0x00 (2 rows) |
- CREATE: Creates an object. (table, index, etc.)
- RUNNING_XACTS: Captures the snapshot with current active transactions.
- INSERT_LEAF: Operation of a B-Tree Index.
- COMMIT: Commits transaction/s.
- DELETE: Deletes rows or columns of objects.
- HOT_UPDATE: Updates rows or columns of objects.
Conclusion
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:
- Speed Up of the WAL Archiving in PostgreSQL 15
- Find the WAL Count Between Two Segments 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.
Download now: PostgreSQL Performance Tuning