RE: [PATCH] Speedup truncates of relation forks

On Wednesday, June 26, 2019 6:10 PM(GMT+9), Adrien Nayrat wrote:
> As far as I remember, you should see "relation" wait events (type lock) on
> standby server. This is due to startup process acquiring AccessExclusiveLock
> for the truncation and other backend waiting to acquire a lock to read the
> table.

Hi Adrien, thank you for taking time to reply.

I understand that RelationTruncate() can block read-only queries on
standby during redo. However, it's difficult for me to reproduce the
test case where I need to catch that wait for relation lock, because
one has to execute SELECT within the few milliseconds of redoing the
truncation of one table.

Instead, I just measured the whole recovery time, smgr_redo(),
to show the recovery improvement compared to head. Please refer below.

[Recovery Test]
I used the same stored functions and configurations in the previous email
& created "test" db.

$ createdb test
$ psql -d test

1. [Primary] Create 10,000 relations.
test=# SELECT create_tables(10000);

2. [P] Insert one row in each table.
test=# SELECT insert_tables(10000);

3. [P] Delete row of each table.
test=# SELECT delfrom_tables(10000);

4. [Standby] WAL application is stopped at Standby server.
test=# SELECT pg_wal_replay_pause();

5. [P] VACUUM is executed at Primary side, and measure its execution time.
test=# \timing on
test=# VACUUM;

Alternatively, you may use:
$ time psql -d test -c 'VACUUM;'
(Note: WAL has not replayed on standby because it's been paused.)

6. [P] Wait until VACUUM has finished execution. Then, stop primary server.
test=# pg_ctl stop -w

7. [S] Resume WAL replay, then promote standby (failover).
I used a shell script to execute recovery & promote standby server
because it's kinda difficult to measure recovery time. Please refer to the script below.
- "SELECT pg_wal_replay_resume();" is executed and the WAL application is resumed.
- "pg_ctl promote" to promote standby.
- The time difference of "select pg_is_in_recovery();" from "t" to "f" is measured.

shell script:

PGDT=/path_to_storage_directory/

if [ "$1" = "resume" ]; then
psql -c "SELECT pg_wal_replay_resume();" test
date +%Y/%m/%d_%H:%M:%S.%3N
pg_ctl promote -D ${PGDT}
set +x
date +%Y/%m/%d_%H:%M:%S.%3N
while [ 1 ]
do
RS=`psql -Atc "select pg_is_in_recovery();" test`
if [ ${RS} = "f" ]; then
break
fi
done
date +%Y/%m/%d_%H:%M:%S.%3N
set -x
exit 0
fi

[Test Results]
shared_buffers = 24GB

1. HEAD
(wal replay resumed)
2019/07/01_08:48:50.326
server promoted
2019/07/01_08:49:50.482
2019/07/01_09:02:41.051

Recovery Time:
13 min 50.725 s -> Time difference from WAL replay to complete recovery
12 min 50.569 s -> Time difference of "select pg_is_in_recovery();" from "t" to "f"

2. PATCH
(wal replay resumed)
2019/07/01_07:34:26.766
server promoted
2019/07/01_07:34:57.790
2019/07/01_07:34:57.809

Recovery Time:
31.043 s -> Time difference from WAL replay to complete recovery
00.019 s -> Time difference of "select pg_is_in_recovery();" from "t" to "f"

[Conclusion]
The recovery time significantly improved compared to head
from 13 minutes to 30 seconds.

Any thoughts?
I'd really appreciate your comments/feedback about the patch and/or test.

Regards,
Kirk Jamison