logical replication busy-waiting on a lock

From: Jeff Janes <jeff(dot)janes(at)gmail(dot)com>
To: pgsql-hackers <pgsql-hackers(at)postgresql(dot)org>
Subject: logical replication busy-waiting on a lock
Date: 2017-05-26 23:25:14
Message-ID: CAMkU=1zHByth0cWStqHS0qspmN0qhJmO6dpoHaAoZJ6=A3hLRA@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

When I create a subscription in the disabled state, and then later doing
"alter subscription sub enable;", on the master I sometimes get a tight
loop of the deadlock detector:

(log_lock_waits is on, of course)

deadlock_timeout is set to 1s, so I don't know why it seems to be running
several times per millisecond.

47462 idle in transaction 2017-05-26 16:05:20.505 PDT LOG: logical
decoding found initial starting point at 1B/7BAC9D50
47462 idle in transaction 2017-05-26 16:05:20.505 PDT DETAIL: Waiting for
transactions (approximately 9) older than 73326615 to end.
47462 idle in transaction waiting 2017-05-26 16:05:21.505 PDT LOG: process
47462 still waiting for ShareLock on transaction 73322726 after 1000.060 ms
47462 idle in transaction waiting 2017-05-26 16:05:21.505 PDT DETAIL:
Process holding the lock: 47457. Wait queue: 47462.
47462 idle in transaction waiting 2017-05-26 16:05:21.506 PDT LOG: process
47462 still waiting for ShareLock on transaction 73322726 after 1000.398 ms
47462 idle in transaction waiting 2017-05-26 16:05:21.506 PDT DETAIL:
Process holding the lock: 47457. Wait queue: 47462.
47462 idle in transaction waiting 2017-05-26 16:05:21.506 PDT LOG: process
47462 still waiting for ShareLock on transaction 73322726 after 1000.574 ms
47462 idle in transaction waiting 2017-05-26 16:05:21.506 PDT DETAIL:
Process holding the lock: 47457. Wait queue: 47462.
47462 idle in transaction waiting 2017-05-26 16:05:21.506 PDT LOG: process
47462 still waiting for ShareLock on transaction 73322726 after 1000.816 ms
47462 idle in transaction waiting 2017-05-26 16:05:21.506 PDT DETAIL:
Process holding the lock: 47457. Wait queue: 47462.
47462 idle in transaction waiting 2017-05-26 16:05:21.506 PDT LOG: process
47462 still waiting for ShareLock on transaction 73322726 after 1001.180 ms
47462 idle in transaction waiting 2017-05-26 16:05:21.506 PDT DETAIL:
Process holding the lock: 47457. Wait queue: 47462.
47462 idle in transaction waiting 2017-05-26 16:05:21.507 PDT LOG: process
47462 still waiting for ShareLock on transaction 73322726 after 1001.284 ms
47462 idle in transaction waiting 2017-05-26 16:05:21.507 PDT DETAIL:
Process holding the lock: 47457. Wait queue: 47462.
47462 idle in transaction waiting 2017-05-26 16:05:21.507 PDT LOG: process
47462 still waiting for ShareLock on transaction 73322726 after 1001.493 ms
.....

And so on out to "after 9616.814", when it finally acquires the lock.

The other process, 47457, is doing the initial COPY of another table as
part of the same publisher/subscriber set.

Cheers,

Jeff

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Mark Kirkwood 2017-05-26 23:35:56 Re: logical replication - still unstable after all these months
Previous Message Kha Nguyen 2017-05-26 22:40:34 Re: Extra Vietnamese unaccent rules