The World of Data

I finally shared the set of functions that I use to process pgBadger raw output.

There will be more documentation, I promise, but at least the code is there, along with two of many presentations.

Enjoy! https://github.com/hettie-d/logs-processing

It has been a while since last time I blogged about any real-database-life problems and investigation. Here is one which I am really happy about, because it took a while and it was not obvious, but I found the root cause of a problem!

The problem has been going on for months: one of the Postgres databases WAL file system was growing with an alarming speed, many times faster than the database itself. Not like we can’t promptly remove the WALs, but this situation made any database restore a reali nightmare. At first, I suspected long transactions with suboptimal backfill algorithms. There were, indeed, a lot of jobs running on a regular basis which could be improved, however, I noticed a couple of things.

First, when the users fixed one of the primary suspects jobs, the situation with WAL growth didn’t change. Second, the rate of the growth couldn’t be explained by these suboptimal jobs: the data volumes they were removing and reloading were still magnitudes smaller than the WAL size we were dealing with. Finally, I decided to do what I should have done from the start – to take a look at what exactly was in these super-fast growing WALs.

Here is what I did:

create extension  pg_walinspect;

select pg_current_wal_insert_lsn();  /* save the result: '17797/A167C8E8' */

select pg_current_wal_insert_lsn() /* save the result : '17797/FEDE0CC8'*/

select * from  pg_get_wal_stats('17797/A167C8E8', '17797/FEDE0CC8', true)
where count>0;

To my amazement, I realized that 97% of the WALs stored the information about locks! To be honest, I didn’t even know that locks are recorded in the WAL files, so I am thankful for gracious Postgres community enlightening me!

Now that I knew where to look, I ran the following:

select * from pg_get_wal_records_info('17797/A167C8E8', '17797/FEDE0CC8')
where resource_manager='Heap'
and record_type='LOCK'

Zooming in:

Next, I found the table which had all these locks:

select * from pg_class where oid =10229951

When I found this_table_name, I was able to inspect the pgBadger database I find the specific statements:

select * 
from this_customer_logs.this_database_log_t_2025_07_25
where query like '%this_table_name%'

As it turned out, although UPDATE seems to be a cause of slowness/lock waits, the UPDATE itself is executed in between 1 and 2 ms when there are no waits. The actual cause of slowness is one slow select executed in a read transaction – see the sequence of events:

Thus, the cause of this gigantic WAL growth was one (actually, two) slow SELECT statement(s)! Who would’ve guessed?!