standby가 뒤처진다

$ pg_basebackup -h pgprimary -D $PGDATA -R -X stream -C -S standby1 -c fast
$ ls $PGDATA/standby.signal && grep primary_conninfo $PGDATA/postgresql.auto.conf
/var/lib/pgsql/18/data/standby.signal
primary_conninfo = 'user=postgres passfile=''/var/lib/pgsql/.pgpass'' channel_binding=prefer host=pgprimary port=5432 sslmode=prefer sslnegotiation=postgres sslcompression=0 sslcertmode=allow sslsni=1 ssl_min_protocol_version=TLSv1.2 gssencmode=prefer krbsrvname=postgres gssdelegation=0 target_session_attrs=any load_balance_hosts=disable'

standby=# SELECT name, setting FROM pg_settings WHERE name IN ('hot_standby_feedback', 'max_standby_streaming_delay', 'log_recovery_conflict_waits') ORDER BY name;
            name             | setting
-----------------------------+---------
 hot_standby_feedback        | off
 log_recovery_conflict_waits | on
 max_standby_streaming_delay | 10000
(3 rows)

primary=# SELECT application_name AS app, state, sent_lsn, replay_lsn,
primary-#        write_lag, flush_lag, replay_lag,
primary-#        pg_size_pretty(pg_wal_lsn_diff(sent_lsn, replay_lsn)) AS replay_gap
primary-# FROM pg_stat_replication;
     app     |   state   | sent_lsn  | replay_lsn |    write_lag    |    flush_lag    |   replay_lag    | replay_gap
-------------+-----------+-----------+------------+-----------------+-----------------+-----------------+------------
 walreceiver | streaming | 0/4000000 | 0/4000000  | 00:00:00.000029 | 00:00:00.000029 | 00:00:00.000029 | 0 bytes
(1 row)

standby=# SELECT pg_last_wal_receive_lsn() AS received, pg_last_wal_replay_lsn() AS replayed,
standby-#        pg_size_pretty(pg_wal_lsn_diff(pg_last_wal_receive_lsn(), pg_last_wal_replay_lsn())) AS gap,
standby-#        now() - pg_last_xact_replay_timestamp() AS since_last_replay;
 received  | replayed  |   gap   | since_last_replay
-----------+-----------+---------+-------------------
 0/4000000 | 0/4000000 | 0 bytes |
(1 row)
standby=# SELECT status, sender_host, written_lsn, flushed_lsn FROM pg_stat_wal_receiver;
  status   | sender_host | written_lsn | flushed_lsn
-----------+-------------+-------------+-------------
 streaming | pgprimary   |             | 0/4000000
(1 row)

R=# SET application_name = 'report';
SET

R=# \timing on
Timing is on.

R=# SELECT count(*), pg_sleep(40) FROM acc;

primary=# UPDATE acc SET v = v + 1;
UPDATE 100000

primary=# VACUUM acc;
VACUUM

primary=# SELECT application_name AS app, state, sent_lsn, replay_lsn,
primary-#        write_lag, flush_lag, replay_lag,
primary-#        pg_size_pretty(pg_wal_lsn_diff(sent_lsn, replay_lsn)) AS replay_gap
primary-# FROM pg_stat_replication;
     app     |   state   | sent_lsn  | replay_lsn |   write_lag    |    flush_lag    |   replay_lag    | replay_gap
-------------+-----------+-----------+------------+----------------+-----------------+-----------------+------------
 walreceiver | streaming | 0/5B82970 | 0/5A829A0  | 00:00:00.00016 | 00:00:00.000472 | 00:00:00.206355 | 1024 kB
(1 row)
standby=# SELECT pg_last_wal_receive_lsn() AS received, pg_last_wal_replay_lsn() AS replayed,
standby-#        pg_size_pretty(pg_wal_lsn_diff(pg_last_wal_receive_lsn(), pg_last_wal_replay_lsn())) AS gap,
standby-#        now() - pg_last_xact_replay_timestamp() AS since_last_replay;
 received  | replayed  |   gap   | since_last_replay
-----------+-----------+---------+-------------------
 0/5B82970 | 0/5A829A0 | 1024 kB | 00:00:04.236133
(1 row)

$ tail -n 400 "$(ls -t $PGDATA/log/*.log | head -1)" | grep -E 'recovery still waiting|conflict' | tail -n 3
2026-09-26 10:34:48.936 UTC [34] LOG:  recovery still waiting after 1034.610 ms: recovery conflict on snapshot

# 세션 R: 앞 명령의 결과를 기다림
ERROR:  canceling statement due to conflict with recovery
DETAIL:  User query might have needed to see row versions that must be removed.
Time: 11643.173 ms (00:11.643)

$ tail -n 400 "$(ls -t $PGDATA/log/*.log | head -1)" | grep -E 'recovery conflict|canceling statement|finished waiting' | tail -n 4
2026-09-26 10:34:48.936 UTC [34] LOG:  recovery still waiting after 1034.610 ms: recovery conflict on snapshot
2026-09-26 10:34:58.712 UTC [72] postgres@postgres/report ERROR:  canceling statement due to conflict with recovery
2026-09-26 10:34:58.718 UTC [34] LOG:  recovery finished waiting after 10816.743 ms: recovery conflict on snapshot

primary=# SELECT application_name AS app, state, sent_lsn, replay_lsn,
primary-#        write_lag, flush_lag, replay_lag,
primary-#        pg_size_pretty(pg_wal_lsn_diff(sent_lsn, replay_lsn)) AS replay_gap
primary-# FROM pg_stat_replication;
     app     |   state   | sent_lsn  | replay_lsn |    write_lag    |    flush_lag    |   replay_lag    | replay_gap
-------------+-----------+-----------+------------+-----------------+-----------------+-----------------+------------
 walreceiver | streaming | 0/5B829A8 | 0/5B829A8  | 00:00:00.000452 | 00:00:00.001044 | 00:00:01.961063 | 0 bytes
(1 row)
standby=# SELECT datname, confl_snapshot, confl_lock, confl_bufferpin, confl_deadlock FROM pg_stat_database_conflicts WHERE datname = 'postgres';
 datname  | confl_snapshot | confl_lock | confl_bufferpin | confl_deadlock
----------+----------------+------------+-----------------+----------------
 postgres |              1 |          0 |               0 |              0
(1 row)

standby=# ALTER SYSTEM SET hot_standby_feedback = on;
ALTER SYSTEM

standby=# SELECT pg_reload_conf();
 pg_reload_conf
----------------
 t
(1 row)

R=# SELECT count(*), pg_sleep(20) FROM acc;

primary=# SELECT application_name AS app, backend_xmin FROM pg_stat_replication;
     app     | backend_xmin
-------------+--------------
 walreceiver |
(1 row)


primary=# SELECT slot_name, active, xmin, age(xmin) AS xmin_age FROM pg_replication_slots;
 slot_name | active | xmin | xmin_age
-----------+--------+------+----------
 standby1  | t      |  755 |        0
(1 row)

primary=# UPDATE acc SET v = v + 1;
UPDATE 100000

primary=# VACUUM (VERBOSE) acc;
INFO:  vacuuming "postgres.public.acc"
INFO:  finished vacuuming "postgres.public.acc": index scans: 0
pages: 0 removed, 885 remain, 885 scanned (100.00% of total), 0 eagerly scanned
tuples: 0 removed, 200000 remain, 100000 are dead but not yet removable
removable cutoff: 755, which was 1 XIDs old when operation ended
frozen: 0 pages from table (0.00% of total) had 0 tuples frozen
visibility map: 0 pages set all-visible, 0 pages set all-frozen (0 were all-visible)
index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed
avg read rate: 0.000 MB/s, avg write rate: 0.000 MB/s
buffer usage: 1825 hits, 0 reads, 0 dirtied
WAL usage: 1 records, 0 full page images, 258 bytes, 0 buffers full
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
VACUUM

primary=# SELECT application_name AS app, state, sent_lsn, replay_lsn,
primary-#        write_lag, flush_lag, replay_lag,
primary-#        pg_size_pretty(pg_wal_lsn_diff(sent_lsn, replay_lsn)) AS replay_gap
primary-# FROM pg_stat_replication;
     app     |   state   | sent_lsn  | replay_lsn |    write_lag    |    flush_lag    |   replay_lag    | replay_gap
-------------+-----------+-----------+------------+-----------------+-----------------+-----------------+------------
 walreceiver | streaming | 0/6F9E910 | 0/6F9E910  | 00:00:00.000104 | 00:00:00.000306 | 00:00:00.002368 | 0 bytes
(1 row)

# 세션 R: 앞 명령의 결과를 기다림
 count  | pg_sleep
--------+----------
 100000 |
(1 row)

Time: 20028.378 ms (00:20.028)

$ pg_ctl -D $PGDATA -w stop -m fast
waiting for server to shut down.... done
server stopped
[exit=0]

primary=# SELECT application_name AS app, state, sent_lsn, replay_lsn,
primary-#        write_lag, flush_lag, replay_lag,
primary-#        pg_size_pretty(pg_wal_lsn_diff(sent_lsn, replay_lsn)) AS replay_gap
primary-# FROM pg_stat_replication;
 app | state | sent_lsn | replay_lsn | write_lag | flush_lag | replay_lag | replay_gap
-----+-------+----------+------------+-----------+-----------+------------+------------
(0 rows)

$ pgbench -i -s 10 -q postgres 2>&1 | tail -n 1
done in 0.50 s (drop tables 0.00 s, create tables 0.01 s, client-side generate 0.36 s, vacuum 0.03 s, primary keys 0.10 s).

primary=# SELECT slot_name, active, restart_lsn,
primary-#        pg_size_pretty(pg_wal_lsn_diff(pg_current_wal_lsn(), restart_lsn)) AS retained
primary-# FROM pg_replication_slots;
 slot_name | active | restart_lsn | retained
-----------+--------+-------------+----------
 standby1  | f      | 0/6FEEFC8   | 123 MB
(1 row)

$ pg_ctl -D $PGDATA -l /var/lib/pgsql/startup.log -w start
waiting for server to start.... done
server started
[exit=0]

primary=# SELECT application_name AS app, state, sent_lsn, replay_lsn,
primary-#        write_lag, flush_lag, replay_lag,
primary-#        pg_size_pretty(pg_wal_lsn_diff(sent_lsn, replay_lsn)) AS replay_gap
primary-# FROM pg_stat_replication;
     app     |   state   | sent_lsn  | replay_lsn |    write_lag    |    flush_lag    |   replay_lag    | replay_gap
-------------+-----------+-----------+------------+-----------------+-----------------+-----------------+------------
 walreceiver | streaming | 0/EB0ED18 | 0/EB0ED18  | 00:00:00.136627 | 00:00:00.138404 | 00:00:00.213931 | 0 bytes
(1 row)