logical_apply_lock_issue.log

application/octet-stream
Filename: logical_apply_lock_issue.log
Type: application/octet-stream
Part: 1
Message: Lock timeouts and unusual spikes in replication lag with logical parallel transaction streaming
Aug 11 01:46:36.040 [2857187]: [660-1] LOG:  logical replication apply worker for subscription "sub1" has started
Aug 11 01:48:10.214 [2857523]: [660-1] LOG:  logical replication apply worker for subscription "sub1" has started
Aug 11 01:48:40.093 [580880]: [1891-1] LOG:  checkpoint complete: wrote 1147764 buffers (9.1%); 0 WAL file(s) added, 35 removed, 337 recycled; write=165.358 s, sync=0.001 s, total=165.397 s; sync files=72, longest=0.001 s, average=0.001 s; distance=6091892 kB, estimate=6091892 kB; lsn=98FB/2B75BE98, redo lsn=98F9/FD0CE6D8
Aug 11 01:49:02.559 [580880]: [1892-1] LOG:  checkpoint starting: wal
Aug 11 01:51:03.003 [2851131]: [656-1] LOG:  automatic vacuum of table "xxxxxxxxxxxxxxxx.public.xxxxxxxxxxxxxxxx": index scans: 1
Aug 11 01:52:35.588 [580880]: [1893-1] LOG:  checkpoint complete: wrote 1417931 buffers (11.3%); 0 WAL file(s) added, 0 removed, 336 recycled; write=212.994 s, sync=0.001 s, total=213.029 s; sync files=54, longest=0.001 s, average=0.001 s; distance=5508911 kB, estimate=6033594 kB; lsn=98FC/7BBD1EE0, redo lsn=98FB/4D49A430
Aug 11 01:52:54.624 [580880]: [1894-1] LOG:  checkpoint starting: wal
Aug 11 01:55:38.926 [580880]: [1895-1] LOG:  checkpoint complete: wrote 1559943 buffers (12.4%); 0 WAL file(s) added, 0 removed, 336 recycled; write=164.266 s, sync=0.002 s, total=164.303 s; sync files=28, longest=0.002 s, average=0.001 s; distance=5503943 kB, estimate=5980629 kB; lsn=98FD/CBBB2B20, redo lsn=98FC/9D38C320
Aug 11 01:55:57.413 [580880]: [1896-1] LOG:  checkpoint starting: wal
Aug 11 01:58:45.570 [2861846]: [660-1] LOG:  logical replication apply worker for subscription "sub1" has started
Aug 11 01:58:46.346 [2857523]: [661-1] LOG:  process 2857523 still waiting for AccessShareLock on remote transaction 295087899 of subscription 2237467148 of database 16423 after 1000.134 ms
Aug 11 01:58:46.347 [2857523]: [661-2] DETAIL:  Process holding the lock: 2857187. Wait queue: 2857523.
Aug 11 01:58:46.347 [2857523]: [661-3] CONTEXT:  processing remote data for replication origin "pg_2237467148" during message type "STREAM STOP" in transaction 295087899
Aug 11 01:58:47.900 [580880]: [1897-1] LOG:  checkpoint complete: wrote 1290085 buffers (10.3%); 0 WAL file(s) added, 0 removed, 336 recycled; write=170.450 s, sync=0.002 s, total=170.488 s; sync files=23, longest=0.001 s, average=0.001 s; distance=5503923 kB, estimate=5932959 kB; lsn=98FF/1BB18FB8, redo lsn=98FD/ED279100
Aug 11 01:59:02.792 [580880]: [1898-1] LOG:  checkpoint starting: wal
Aug 11 01:59:08.738 [2857187]: [661-1] LOG:  logical replication apply worker will serialize the remaining changes of remote transaction 295096568 to a file
Aug 11 01:59:08.738 [2857187]: [661-2] CONTEXT:  processing remote data for replication origin "pg_2237467148" during message type "UPDATE" in transaction 295096568
Aug 11 01:59:14.773 [2857187]: [662-1] LOG:  process 2857187 still waiting for AccessShareLock on remote transaction 295096568 of subscription 2237467148 of database 16423 after 1000.102 ms
Aug 11 01:59:14.773 [2857187]: [662-2] DETAIL:  Process holding the lock: 2861846. Wait queue: 2857187.
Aug 11 01:59:14.773 [2857187]: [662-3] CONTEXT:  processing remote data for replication origin "pg_2237467148" during message type "STREAM COMMIT" in transaction 295096568, finished at 974F/C36A2AD0
Aug 11 01:59:15.346 [2857523]: [662-1] LOG:  process 2857523 still waiting for AccessShareLock on remote transaction 295087899 of subscription 2237467148 of database 16423 after 30000.111 ms
Aug 11 01:59:15.346 [2857523]: [662-2] DETAIL:  Process holding the lock: 2857187. Wait queue: 2857523.
Aug 11 01:59:15.347 [2857523]: [662-3] CONTEXT:  processing remote data for replication origin "pg_2237467148" during message type "STREAM STOP" in transaction 295087899
Aug 11 01:59:27.838 [2857187]: [663-1] LOG:  process 2857187 still waiting for AccessShareLock on remote transaction 295096568 of subscription 2237467148 of database 16423 after 14064.683 ms
Aug 11 01:59:27.838 [2857187]: [663-2] DETAIL:  Process holding the lock: 2861846. Wait queue: 2857187.
Aug 11 01:59:27.838 [2857187]: [663-3] CONTEXT:  processing remote data for replication origin "pg_2237467148" during message type "STREAM COMMIT" in transaction 295096568, finished at 974F/C36A2AD0
Aug 11 01:59:28.373 [2857187]: [664-1] LOG:  process 2857187 still waiting for AccessShareLock on remote transaction 295096568 of subscription 2237467148 of database 16423 after 14600.238 ms
Aug 11 01:59:28.373 [2857187]: [664-2] DETAIL:  Process holding the lock: 2861846. Wait queue: 2857187.
Aug 11 01:59:28.373 [2857187]: [664-3] CONTEXT:  processing remote data for replication origin "pg_2237467148" during message type "STREAM COMMIT" in transaction 295096568, finished at 974F/C36A2AD0
Aug 11 01:59:29.070 [2857187]: [665-1] LOG:  process 2857187 still waiting for AccessShareLock on remote transaction 295096568 of subscription 2237467148 of database 16423 after 15297.571 ms
Aug 11 01:59:29.070 [2857187]: [665-2] DETAIL:  Process holding the lock: 2861846. Wait queue: 2857187.
Aug 11 01:59:29.070 [2857187]: [665-3] CONTEXT:  processing remote data for replication origin "pg_2237467148" during message type "STREAM COMMIT" in transaction 295096568, finished at 974F/C36A2AD0
Aug 11 01:59:29.478 [2857187]: [666-1] LOG:  process 2857187 still waiting for AccessShareLock on remote transaction 295096568 of subscription 2237467148 of database 16423 after 15705.752 ms
Aug 11 01:59:29.478 [2857187]: [666-2] DETAIL:  Process holding the lock: 2861846. Wait queue: 2857187.
Aug 11 01:59:29.478 [2857187]: [666-3] CONTEXT:  processing remote data for replication origin "pg_2237467148" during message type "STREAM COMMIT" in transaction 295096568, finished at 974F/C36A2AD0
Aug 11 01:59:43.773 [2857187]: [667-1] ERROR:  canceling statement due to lock timeout
Aug 11 01:59:43.773 [2857187]: [667-2] CONTEXT:  processing remote data for replication origin "pg_2237467148" during message type "STREAM COMMIT" in transaction 295096568, finished at 974F/C36A2AD0
Aug 11 01:59:43.773 [2857523]: [663-1] FATAL:  terminating logical replication worker due to administrator command
Aug 11 01:59:43.774 [2857523]: [663-2] CONTEXT:  processing remote data for replication origin "pg_2237467148" during message type "STREAM STOP" in transaction 295087899
Aug 11 01:59:43.784 [2861846]: [661-1] FATAL:  terminating logical replication worker due to administrator command
Aug 11 01:59:43.823 [2857187]: [668-1] LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp2857187.0.fileset/2237467148-295096568.changes.0", size 354120868
Aug 11 01:59:43.826 [2862097]: [660-1] LOG:  logical replication apply worker for subscription "sub1" has started
Aug 11 01:59:43.827 [2862097]: [661-1] ERROR:  replication origin with ID 1 is already active for PID 2857187
Aug 11 01:59:43.828 [580876]: [660-1] LOG:  background worker "logical replication apply worker" (PID 2862097) exited with exit code 1
Aug 11 01:59:43.829 [580876]: [661-1] LOG:  background worker "logical replication apply worker" (PID 2857187) exited with exit code 1
Aug 11 01:59:44.165 [580876]: [662-1] LOG:  background worker "logical replication parallel worker" (PID 2861846) exited with exit code 1
Aug 11 01:59:45.167 [580876]: [663-1] LOG:  background worker "logical replication parallel worker" (PID 2857523) exited with exit code 1