2

I had trouble in my environment which is related to autovacuum and now I think I understand how this occurs. However, this is kind of a rare issue and so I want to get some advice regarding this issue.

Our environment before the upgrade was:

  • RDS PostgreSQL 9.3, Multi-AZ and 4 Read Replica.
  • hot_standby_feedback = 1
  • max_standby_streaming_delay = -1
  • statement_timeout = 0 ( application also had no setting. )

I am a beginner to PostgreSQL (I've been working as a MySQL Admin) and had the task of upgrading to version 9.6. I should have done an investigation of the database beforehand, but couldn't. Then after the upgrade, lots of SELECT query waits occurred in the read replicas and I had no idea why this was happening.

I did some deeper investigation and I found that it was because of autovacuum. Here is the mailing archive of PostgreSQL that refers to the issue I am encountering:

WIP: long transactions on hot standby feedback replica / proof of concept

Our PostgreSQL was in the awful situation:
- There were long transactions (batch jobs that forgot to close transactions) that had kept locks on the 2 tables in the 9.3 version. I guess it kept on going more that one year at least. (Before I joined, there was nobody that be able to manage PostgreSQL.) Because of this, the 2 tables were hugely bloated. The actual amount of data size that the application is using is about 2GB although 2 tables had been grown to about 100GB each.
- I guess the two tables had not been the candidate of autovacuum because of the long transaction.
- Because the two tables had not been autovacuumed so long time, the tables had the huge number of live tuples.

As far as I know, when you do the major upgrade in RDS PostgreSQL, pg_upgrade works, and this includes concurrent vacuum operation. So after upgrade to 9.6, the two table had vacuumed but did not return free pages to OS. I used pgstattuple extension and this showed the two table had a huge amount of free pages. It showed 100GB as approx_free_space so it means almost all pages were free. This means the live tuple in the era of 9.3 became free pages because of concurrent vacuum which was done by pg_upgrade.

The two tables are always (I mean it 24h) accepting SELECT queries from application in the read replicas but not in the Master.

Here is an issue I had. When autovauum were running in Master against the two tables, a lots of SELECT queries in the read replicas were waiting for a ShareAccessLock. This lead to system fault because these queries never returned the result for a long time.

What's more, the error log just said

LOG: process <pid> still waiting for AccessShareLock on relation of <oid> of database <oid> after xxx ms at character xxxx ..." DETAIL: Process holding the lock: <pid> <pid> <pid> <pid> ... ( these pid were SELECT queries and lots of these were waiting)

As I showed, the error log did not tell "ERROR" or "FATAL" messages.

I was first confused how should I understand this log, because AccessShareLock shoud contend with other locks though we never did operation which gets any locks against two table while this was happening. I surely cheked error logs, pg_locks and pg_stat_activity and nothing that is suspious one that held any locks against the two table.

At the time this issue happened, I changed autovacuum parameter to false in Master to stop autovacuum and killed the autovacuum process against the two tables. And finally the wait query in the read replica disappeared.

As the link of mailing list archive says, autovacuum ( lazy_vacuum_rel ) tries to get an ExclusiveLock to truncate free pages in Master.

It gives up ExclusiveLock in master, but when WAL which includes ExclusiveLock query ships to read replicas, this WAL just replays without any hesitation even if PostgreSQL set with parameter I wrote at the begging. (I mean hot_standby_feedback!)

I assume that because of this, in our situation, that there were the huge amount of free pages, many free pages were being continuously truncated in Master, and lots of these were replaying and lots of SELECT queries were waiting in the read replicas.

As workaround, I set by alter table to not to be autovaccumed against the two table because I am afraid of happening this isuue again. Now autovaccum parameter got back to true.

So here is I want to discuses (and would like to know)

  1. Is this situation possibly happening? Is my guess correct?
  2. The error log told there were a lots of SELECT queries were waiting but did not tell what pid process hold AccessExclusiceLock against the two table. So I tried to find by checking pg_locks table but it cannot tell. I guess the reason why I could not get pid from pg_locks is that the process was bgwriter replaying WAL. I know we cannnot find bgwriter process from pg_stat_activity and I guess it also apply to pg_locks.
  3. Does pg_repack extension possibly trigger this issue?? I assume with the logic of pg_repack there is no chance of doing it.
  4. As far as I know, we cannot prevent from getting exclusive lock by autovacuum in read replica with this pattern. Also I think we cannot predict the timing this happen because I don't know the amount of freepages which triggers this AccessExclusiceLock situation, because it occurs over a long period. (I know my case is extreme.) So what would be the best practice to prevent this issue?

My idea is:

  • of course, never occurs long transaction. To do this, set statement_timeout and idle_in_transaction_session_timeout to a proper value.
  • keep watching or hopefully monitor value of free pages by using pgstattple.

I would be very appreciate if you give me any advice. Thanks.

3
  • How long does each individual select query last when there is no truncation replay being requested?
    – jjanes
    Apr 28, 2018 at 12:01
  • We set log_min_duration_statement at 2 seconds and this query is recorded but not all the time. Also it goes up to 5 seconds at the maximam seconds.
    – eger
    Apr 30, 2018 at 6:57
  • How long is any transaction on the replica? That is, how long is the longest statement that can potentially be doing the blocking, not just the one that is getting blocked? Do you have multi-statement transactions with a long gap between statements?
    – jjanes
    May 6, 2018 at 16:33

1 Answer 1

1
  1. Is this situation possibly happening? Is my guess correct?

yes, this definitely will happen.

If autovacuum finds a bunch of empty pages at the end of the table, it will try to truncate those pages away to return the space to the OS. It will need to obtain an Access Exclusive lock to do this, and that lock is recorded in WAL and is replayed by and held by the replica server for the duration of the truncation (and replay of the truncation WAL).

When Master is being auto vacuumed, Is slave gettting exclusive lock on its table to apply WAL?

  1. The error log told there were ...

The startup process is holding the lock.

| pid | backend_start | wait_event_type | wait_event | backend_type
| xxxx | 2022-07-05 16:52:27.864415+00 | Activity | WalReceiverMain | wal replay

every operation on primary instance has to be replayed on standby instance as well include the Exclusive Access lock

I guess the reason why I could not get pid from pg_locks is that the process was bgwriter replaying WAL.

I guess the user you are using doesn't have enough permission. you should use admin user.

  1. Does pg_repack extension possibly trigger this issue?? I assume with the logic of pg_repack there is no chance of doing it.

WAL Replay process triggered this issue.

  1. As far as I know, we cannot prevent from getting exclusive lock by autovacuum in read replica with this pattern. Also I think we cannot predict the timing this happen because I don't know the amount of freepages which triggers this AccessExclusiceLock situation, because it occurs over a long period. (I know my case is extreme.) So what would be the best practice to prevent this issue?

After PG12, we can avoid this issue by disabling TRUNCATE, running it manually at low traffic times https://www.postgresql.org/docs/12/sql-vacuum.html

In simple words, if the data structure is below, there is a risk that WAL will hold a lock after AutoVacuum.

Case 1: Write data to Pages → Remove Data/Pages from tail of the Table → Vacuum → Vacuum Truncate enter image description here

Create Test Table

create table test_page
(
   test_key int not null,
   test_value text
);

Insert Test Data to fill the pages (5000 records)

CREATE SEQUENCE serial_page START 1;
do $$
begin
for r in 1..5000 loop
insert into test_page values (nextval('serial_page'), '...');
end loop;
end;
$$;

check the pages

select count(1) as "number of pages"
    from pg_freespace('test_page');
 
number of pages|
---------------+
             32|

remove the data/pages from the tail of the table

delete from test_page where test_key > 2000;

check the log (Pages Truncated)

2023-06-09 18:12:25.991 CST,,,34191,,6482fb09.858f,1,,2023-06-09 18:12:25 CST,6/5548,1412,LOG,00000,"automatic vacuum of table ""core.public.test_page"": index scans: 0
pages: 19 removed, 13 remain, 0 skipped due to pins, 0 skipped frozen
tuples: 3000 removed, 2000 remain, 0 are dead but not yet removable, oldest xmin: 1412
index scan not needed: 20 pages from table (62.50% of total) had 3000 dead item identifiers removed
avg read rate: 32.095 MB/s, avg write rate: 20.270 MB/s
buffer usage: 79 hits, 38 misses, 24 dirtied
WAL usage: 63 records, 21 full page images, 42623 bytes
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s",,,,,,,,,"","autovacuum worker",,0

Case 2: Write data to Pages → Remove Data/Pages from the middle(head) of the Table → Vacuum → Vacuum Truncate not happened → Write new data to Table/Pages → Remove Old Data/Pages from the original tail of the Table → Vacuum → Vacuum Truncate enter image description here

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.