Postgresql 10 create subscription hangs
https://dba.stackexchange.com/questions/191755
-
10-10-2020 - |
italiano
english
français
española
中国
日本の
العربية
Deutsch
한국어
Português
RussianQuestion
On my local machine, I just upgraded to the latest postgres.app to get version 10. Before doing this, I ran pg_dumpall on the 9.6 database and then after installing version 10, I executed the script to re-create the databases, users, etc... I also changed the wal_level to logical after running the script from dumpall and updated some logging settings.
I first created a subscription in the dot database (as superuser)
bill=# \connect dot;
You are now connected to database "dot" as user "bill".
dot=# create publication foo for table dot.item;
CREATE PUBLICATION
There are about 39k rows in the item table, so it shouldn't take that long to sync the data.
Next, I create a new database called dot2 owned by the same user as the dot database, and I created an empty item table in the same schema as it exists in the dot database, and then I tried to subscribe to the the publication in the other database (also as superuser).
bill=# \connect dot2;
You are now connected to database "dot2" as user "bill".
dot2=# create subscription bar connection 'host=localhost port=5432 dbname=dot connect_timeout=10' PUBLICATION foo;
However, this just hangs. It does not return.
In my log, all I see is this...
2017-11-26 21:36:52.828 EST bill@dot2 54567 [local] STATEMENT: create subscription bar connection 'host=localhost port=5432 dbname=dot connect_timeout=10' PUBLICATION foo;
2017-11-26 21:36:55.122 EST bill@dot 54978 ::1(61990) LOG: duration: 9.328 ms statement: SELECT DISTINCT t.schemaname, t.tablename
FROM pg_catalog.pg_publication_tables t
WHERE t.pubname IN ('foo')
2017-11-26 21:36:55.126 EST bill@dot 54978 ::1(61990) LOG: logical decoding found initial starting point at 0/4584A5A8
2017-11-26 21:36:55.126 EST bill@dot 54978 ::1(61990) DETAIL: Waiting for transactions (approximately 1) older than 1613 to end.
Attempting to look in pg_stat_activity (disclaimer -- I don't know what I'm doing here) and I see this in the publish database...
edit Adding more details from pg_state. null values elided for (some) brevity.
dot=# select * from pg_stat_activity;
-[ RECORD 1 ]----+-------------------------------------------------------------------------------------------------------------
pid | 54323
backend_start | 2017-11-26 21:04:40.467211-05
wait_event_type | Activity
wait_event | AutoVacuumMain
backend_type | autovacuum launcher
-[ RECORD 2 ]----+-------------------------------------------------------------------------------------------------------------
pid | 54325
usesysid | 10
usename | postgres
backend_start | 2017-11-26 21:04:40.467857-05
wait_event_type | Activity
wait_event | LogicalLauncherMain
backend_type | background worker
-[ RECORD 3 ]----+-------------------------------------------------------------------------------------------------------------
datid | 16391
datname | dot
pid | 54978
usesysid | 16384
usename | bill
application_name | bar
client_addr | ::1
client_port | 61990
backend_start | 2017-11-26 21:36:55.110362-05
xact_start |
query_start | 2017-11-26 21:36:55.113552-05
state_change | 2017-11-26 21:36:55.122976-05
wait_event_type | Lock
wait_event | transactionid
state | idle
query | SELECT DISTINCT t.schemaname, t.tablename +
| FROM pg_catalog.pg_publication_tables t +
| WHERE t.pubname IN ('foo')
backend_type | walsender
-[ RECORD 4 ]----+-------------------------------------------------------------------------------------------------------------
datid | 16391
datname | dot
pid | 54533
usesysid | 16384
usename | bill
application_name | psql
client_port | -1
backend_start | 2017-11-26 21:07:00.309111-05
xact_start | 2017-11-26 22:16:11.140318-05
query_start | 2017-11-26 22:16:11.140318-05
state_change | 2017-11-26 22:16:11.140321-05
state | active
backend_xmin | 1612
query | select * from pg_stat_activity;
backend_type | client backend
-[ RECORD 5 ]----+-------------------------------------------------------------------------------------------------------------
datid | 18611
datname | dot2
pid | 54567
usesysid | 16384
usename | bill
application_name | psql
client_port | -1
backend_start | 2017-11-26 21:09:12.969232-05
xact_start | 2017-11-26 21:36:55.106831-05
query_start | 2017-11-26 21:36:55.106831-05
state_change | 2017-11-26 21:36:55.106835-05
wait_event_type | Client
wait_event | LibPQWalReceiverReceive
state | active
backend_xid | 1612
backend_xmin | 1612
query | create subscription bar connection 'host=localhost port=5432 dbname=dot connect_timeout=10' PUBLICATION foo;
backend_type | client backend
-[ RECORD 6 ]----+-------------------------------------------------------------------------------------------------------------
pid | 54321
backend_start | 2017-11-26 21:04:40.466525-05
wait_event_type | Activity
wait_event | BgWriterMain
backend_type | background writer
-[ RECORD 7 ]----+-------------------------------------------------------------------------------------------------------------
pid | 54320
backend_start | 2017-11-26 21:04:40.466302-05
wait_event_type | Activity
wait_event | CheckpointerMain
backend_type | checkpointer
-[ RECORD 8 ]----+-------------------------------------------------------------------------------------------------------------
pid | 54322
backend_start | 2017-11-26 21:04:40.466712-05
wait_event_type | Activity
wait_event | WalWriterMain
backend_type | walwriter
Adding pg_locks on request. Again, null values are elided.
dot=# select * from pg_locks;
-[ RECORD 1 ]------+-----------------
locktype | relation
database | 18611
relation | 6102
virtualtransaction | 5/16
pid | 54567
mode | RowExclusiveLock
granted | t
fastpath | t
-[ RECORD 2 ]------+-----------------
locktype | relation
database | 18611
relation | 18635
virtualtransaction | 5/16
pid | 54567
mode | AccessShareLock
granted | t
fastpath | t
-[ RECORD 3 ]------+-----------------
locktype | virtualxid
virtualxid | 5/16
virtualtransaction | 5/16
pid | 54567
mode | ExclusiveLock
granted | t
fastpath | t
-[ RECORD 4 ]------+-----------------
locktype | relation
database | 16391
relation | 11577
virtualtransaction | 4/21
pid | 54533
mode | AccessShareLock
granted | t
fastpath | t
-[ RECORD 5 ]------+-----------------
locktype | virtualxid
virtualxid | 4/21
virtualtransaction | 4/21
pid | 54533
mode | ExclusiveLock
granted | t
fastpath | t
-[ RECORD 6 ]------+-----------------
locktype | transactionid
transactionid | 1612
virtualtransaction | 5/16
pid | 54567
mode | ExclusiveLock
granted | t
fastpath | f
-[ RECORD 7 ]------+-----------------
locktype | object
database | 0
classid | 6100
objid | 18661
objsubid | 0
virtualtransaction | 5/16
pid | 54567
mode | AccessShareLock
granted | t
fastpath | f
-[ RECORD 8 ]------+-----------------
locktype | transactionid
transactionid | 1612
virtualtransaction | 3/0
pid | 54978
mode | ShareLock
granted | f
fastpath | f
-[ RECORD 9 ]------+-----------------
locktype | relation
database | 0
relation | 6100
virtualtransaction | 5/16
pid | 54567
mode | RowExclusiveLock
granted | t
fastpath | f
-[ RECORD 10 ]-----+-----------------
locktype | object
database | 0
classid | 1260
objid | 16384
objsubid | 0
virtualtransaction | 5/16
pid | 54567
mode | AccessShareLock
granted | t
fastpath | f
I've tried restarting the database, and I've shut down any processes that might connect to it. The only thing that I'm using that would connect to it are the two psql instances that I'm using to connect to both pub and sub databases.
Any idea why this occurs or what I should look at to figure out why it's waiting?
Solution
From the docs:
Creating a subscription that connects to the same database cluster (for example, to replicate between databases in the same cluster or to replicate within the same database) will only succeed if the replication slot is not created as part of the same command. Otherwise, the CREATE SUBSCRIPTION call will hang. To make this work, create the replication slot separately (using the function pg_create_logical_replication_slot with the plugin name pgoutput) and create the subscription using the parameter create_slot = false. This is an implementation restriction that might be lifted in a future release.
