have a strange trouble with getting new rows on replica on PostgreSQL on AWS. I have master database on AWS with constant flow inserts/updates not with big rate. And these changes are replicated through WAL streaming to replica db. When i do query on replica to get new fresh rows written to master all works fine. When i do long read query on this replica, i stop getting new data in other transactions to same replica, though i still can get data before long scan transaction started.
I tried to look at locks and pg_activity table and could not get any meaningful information about appeared locks. From knowhelege i have, to lock some rows PG have to lock resource in AccessExclusive mode. Locks i see in table which made by long query on replica all are in AccessShare mode and no other exlusive locks are there. From my perspective, this looks like that when i do long query on replica new rows imported by WAL parsing are getting locked for reading.
What other ways or tools can i use to understand problem and find the cause?
Here are commands and text description i used for debug:
- Trying to query replica locks without any long running queries:
SELECT lock.locktype,
lock.relation::regclass,
lock.mode,
lock.transactionid AS tid,
lock.virtualtransaction AS vtid,
lock.pid,
lock.granted
FROM pg_catalog.pg_locks LOCK
LEFT JOIN pg_catalog.pg_database db ON db.oid = lock.database
WHERE (db.datname = 'DB'
OR db.datname IS NULL)
AND NOT lock.pid = pg_backend_pid()
ORDER BY lock.pid;
locktype | relation | mode | tid | vtid | pid | granted
------------+----------+---------------+-----+------+-----+---------
virtualxid | | ExclusiveLock | | 1/0 | 352 | t
(1 row)
geting only virtualxid of select locks query
- Running long scan/index scan query and looking for locks, activity table:
run long query:
SELECT id,
created_at
FROM tbl
ORDER BY created_at DESC
LIMIT 10000000;
after that any short query like below stops giving new rows updated on master and replicated to replica where all queries are executed:
SELECT id,
created_at
FROM tbl
ORDER BY created_at DESC
LIMIT 10;
trying to find locking reason:
SELECT lock.locktype,
lock.relation::regclass,
lock.mode,
lock.transactionid AS tid,
lock.virtualtransaction AS vtid,
lock.pid,
lock.granted
FROM pg_catalog.pg_locks LOCK
LEFT JOIN pg_catalog.pg_database db ON db.oid = lock.database
WHERE (db.datname = 'DB'
OR db.datname IS NULL)
AND NOT lock.pid = pg_backend_pid()
ORDER BY lock.pid;
locktype | relation | mode | tid | vtid | pid | granted
------------+----------------------------------------------------+-----------------+-----+-----------+-------+---------
virtualxid | | ExclusiveLock | | 1/0 | 352 | t
relation | "IX_tbl_001" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_002" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_003" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_004" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_005" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_005" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_007" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_008" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_009" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_010" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_011" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_012" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_013" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "PK_tbl" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "tbl" | AccessShareLock | | 5/1231551 | 24973 | t
virtualxid | | ExclusiveLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_014" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_015" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_016" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_017" | AccessShareLock | | 5/1231551 | 24973 | t
relation | "IX_tbl_018" | AccessShareLock | | 5/1231551 | 24973 | t
SELECT
pid,
backend_start,
query_start,
state_change,
wait_event_type,
wait_event,
query,
backend_type
FROM
pg_stat_activity;
-[ RECORD 1 ]---+---------------------------------------------------------------------------
pid | 461
backend_start | 2023-03-04 07:17:45.420192+00
query_start | 2023-03-05 14:48:19.722021+00
state_change | 2023-03-05 14:48:19.722038+00
wait_event_type | Client
wait_event | ClientRead
query | SELECT 1
backend_type | client backend
-[ RECORD 2 ]---+---------------------------------------------------------------------------
pid | 28583
backend_start | 2023-03-04 14:29:51.138626+00
query_start | 2023-03-05 14:48:21.916923+00
state_change | 2023-03-05 14:48:21.916971+00
wait_event_type | Client
wait_event | ClientRead
query | COMMIT
backend_type | client backend
-[ RECORD 3 ]---+---------------------------------------------------------------------------
pid | 28584
backend_start | 2023-03-04 14:29:52.091085+00
query_start | 2023-03-05 14:47:52.314253+00
state_change | 2023-03-05 14:47:52.314281+00
wait_event_type | Client
wait_event | ClientRead
query | ROLLBACK
backend_type | client backend
-[ RECORD 4 ]---+---------------------------------------------------------------------------
pid | 22783
backend_start | 2023-03-05 14:31:10.44282+00
query_start | 2023-03-05 14:48:22.722693+00
state_change | 2023-03-05 14:48:22.722695+00
wait_event_type |
wait_event |
query | SELECT +
| pid, +
| backend_start, +
| query_start, +
| state_change, +
| wait_event_type, +
| wait_event, +
| query, +
| backend_type +
| FROM pg_stat_activity;
backend_type | client backend
-[ RECORD 5 ]---+---------------------------------------------------------------------------
pid | 23849
backend_start | 2023-03-05 14:47:55.602716+00
query_start | 2023-03-05 14:48:11.454558+00
state_change | 2023-03-05 14:48:11.454561+00
wait_event_type | Client
wait_event | ClientWrite
query | select id, created_at from tbl order by created_at desc limit 10000000;
backend_type | client backend
[ RECORD 6 ]---+---------------------------------------------------------------------------
pid | 373
backend_start | 2023-03-04 07:17:44.493326+00
query_start |
state_change |
wait_event_type | Activity
wait_event | RecoveryWalStream
query |
backend_type | startup
-[ RECORD 7 ]---+---------------------------------------------------------------------------
pid | 383
backend_start | 2023-03-04 07:17:44.612868+00
query_start |
state_change |
wait_event_type | Activity
wait_event | BgWriterHibernate
query |
backend_type | background writer
-[ RECORD 8 ]---+---------------------------------------------------------------------------
pid | 382
backend_start | 2023-03-04 07:17:44.613552+00
query_start |
state_change |
wait_event_type | Activity
wait_event | CheckpointerMain
query |
backend_type | checkpointer
-[ RECORD 9 ]---+---------------------------------------------------------------------------
pid | 1065
backend_start | 2023-03-04 07:18:49.420368+00
query_start |
state_change |
wait_event_type | Activity
wait_event | WalReceiverMain
query |
backend_type | walreceiver
Postgres config:
here i compare settings of local PG where all works well (first value) and replica (second value)
'archive_mode': ('off', 'on'),
'archive_timeout': ('0', '300'),
'autovacuum_analyze_scale_factor': ('0.1', '0.05'),
'autovacuum_naptime': ('60', '15'),
'autovacuum_vacuum_cost_limit': ('-1', '200'),
'autovacuum_vacuum_scale_factor': ('0.2', '0.1'),
'checkpoint_completion_target': ('0.5', '0.9'),
'data_checksums': ('off', 'on'),
'effective_cache_size': ('524288', '486132'),
'huge_pages': ('try', 'on'),
'idle_in_transaction_session_timeout': ('0', '86400000'),
'jit': ('on', 'off'),
'listen_addresses': ('localhost', '*'),
'log_autovacuum_min_duration': ('-1', '10000'),
'log_checkpoints': ('off', 'on'),
'log_file_mode': ('0600', '0644'),
'log_rotation_age': ('1440', '60'),
'logging_collector': ('off', 'on'),
'maintenance_work_mem': ('65536', '127510'),
'max_connections': ('100', '5000'),
'max_replication_slots': ('10', '20'),
'max_stack_depth': ('2048', '6144'),
'max_standby_archive_delay': ('30000', '100000'),
'max_standby_streaming_delay': ('30000', '60000'),
'max_wal_senders': ('10', '20'),
'max_wal_size': ('1024', '2048'),
'max_worker_processes': ('8', '32'),
'min_wal_size': ('80', '192'),
'pg_stat_statements.max': ('', '5000'),
'pg_stat_statements.save': ('', 'on'),
'pg_stat_statements.track': ('', 'top'),
'pg_stat_statements.track_planning': ('', 'off'),
'pg_stat_statements.track_utility': ('', 'on'),
'server_version_num': ('130009', '130007'),
'shared_buffers': ('16384', '243066'),
'tcp_keepalives_count': ('9', '2'),
'tcp_keepalives_idle': ('7200', '300'),
'tcp_keepalives_interval': ('75', '30'),
'track_activity_query_size': ('1024', '4096'),
'track_functions': ('none', 'pl'),
'track_io_timing': ('off', 'on'),
'transaction_read_only': ('off', 'on'),
'unix_socket_permissions': ('0777', '0700'),
'vacuum_cost_page_miss': ('10', '5'),
'wal_buffers': ('512', '7595'),
'wal_compression': ('off', 'on'),
'wal_keep_size': ('0', '2048'),
'wal_receiver_timeout': ('60000', '30000'),
'wal_segment_size': ('16777216', '67108864'),
'wal_sender_timeout': ('60000', '30000')
Update:
tried to check views pg_stat_database_conflicts and pg_stat_replication.
from pg_stat_database_conflicts I see that there are "confl_snapshot" conflicts.
According to the article, the most likely reason for it is "Snapshot replication conflicts".
There is also a topic on recovery conflicts.
As I got from this topic and the article, I can eliminate from replica queries cancelling by tuning
hot_standby_feedback parameter, thus making the master keep data used by the query on standby. And if this query never ends dead tuples on master will never be deleted.
Also, in my queries i did not see any replay_lsn lags, but saw confl_snapshots conflicts:
DB=> select * from pg_stat_database_conflicts where datname='DB';
-[ RECORD 1 ]----+--------
datid | 16416
datname | DB
confl_tablespace | 0
confl_lock | 0
confl_snapshot | 4
confl_bufferpin | 0
confl_deadlock | 0
DB=> select * from pg_stat_replication;
-[ RECORD 1 ]----+-------------
pid | 399
usesysid | 16396
usename | rdsrepladmin
application_name | walreceiver
client_addr |
client_hostname |
client_port |
backend_start |
backend_xmin |
state |
sent_lsn |
write_lsn |
flush_lsn |
replay_lsn |
write_lag |
flush_lag |
replay_lag |
sync_priority |
sync_state |
reply_time |
-[ RECORD 2 ]----+-------------
pid | 398
usesysid | 16396
usename | rdsrepladmin
application_name | walreceiver
client_addr |
client_hostname |
client_port |
backend_start |
backend_xmin |
state |
sent_lsn |
write_lsn |
flush_lsn |
replay_lsn |
write_lag |
flush_lag |
replay_lag |
sync_priority |
sync_state |
reply_time |
