ANALYZE locks pg_listener in EXCLUSIVE for long time?

Philip Warner <pjw@rhyme.com.au> writes:

Does this mean that ANALYZE will take an exclusive lock on pg_listener
until the ANALYZE finishes? Or is there some other cause?

ANALYZE does not take an exclusive lock on anything. However, the
async.c functions want AccessExclusiveLock on pg_listener, so they
quite possibly would get blocked by ANALYZE's not-so-exclusive lock.

Possibly we could reduce the strength of the lock taken by the async.c
functions ... I haven't thought hard about it. The long-term answer is
certainly a wholesale rewrite of the listen/notify mechanism.

regards, tom lane

Tom Lane wrote:

Philip Warner <pjw@rhyme.com.au> writes:

Does this mean that ANALYZE will take an exclusive lock on pg_listener
until the ANALYZE finishes? Or is there some other cause?

ANALYZE does not take an exclusive lock on anything. However, the
async.c functions want AccessExclusiveLock on pg_listener, so they
quite possibly would get blocked by ANALYZE's not-so-exclusive lock.

Possibly we could reduce the strength of the lock taken by the async.c
functions ... I haven't thought hard about it. The long-term answer is
certainly a wholesale rewrite of the listen/notify mechanism.

Gavin was working on it a while ago but I am not sure how far he got.

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

At 12:45 PM 3/05/2004, Tom Lane wrote:

Possibly we could reduce the strength of the lock taken by the async.c
functions

If possible, this seems like a great option. We currently have a large
database with several hundred users who get locked out for as much as half
an hour while ANALYZE runs.

The data in the database is extremely dynamic, so the analyze needs to be
run regularly; we could run less often but this will just mean the problem
happens once per week instead of once per day.

Would ACCESS SHARE be OK?

----------------------------------------------------------------
Philip Warner | __---_____
Albatross Consulting Pty. Ltd. |----/ - \
(A.B.N. 75 008 659 498) | /(@) ______---_
Tel: (+61) 0500 83 82 81 | _________ \
Fax: (+61) 03 5330 3172 | ___________ |
Http://www.rhyme.com.au | / \|
| --________--
PGP key available upon request, | /
and from pgp.mit.edu:11371 |/

Philip Warner <pjw@rhyme.com.au> writes:

If possible, this seems like a great option. We currently have a large
database with several hundred users who get locked out for as much as half
an hour while ANALYZE runs.

If it takes half an hour to ANALYZE pg_listener, I think that ANALYZE is
not your real problem :-(. You need a much more aggressive vacuuming
policy on that table. Maybe a cron job issuing "vacuum pg_listener"
once a minute would do? And get the size of the table knocked down to
something less stratospheric to begin with --- perhaps stop all the
listeners while you TRUNCATE the table.

The existing listen/notify infrastructure isn't really designed for
notification rates exceeding a few events per minute ...

regards, tom lane

Philip Warner <pjw@rhyme.com.au> writes:

Would ACCESS SHARE be OK?

Certainly not, since the point of the locks in async.c is that only one
backend should execute those routines at a time. ExclusiveLock might
work okay ... but I still haven't thought hard about it ...

regards, tom lane

At 01:46 PM 3/05/2004, Tom Lane wrote:

If it takes half an hour to ANALYZE pg_listener, I think that ANALYZE is
not your real problem :-(. You need a much more aggressive vacuuming
policy on that table. Maybe a cron job issuing "vacuum pg_listener"
once a minute would do? And get the size of the table knocked down to
something less stratospheric to begin with --- perhaps stop all the
listeners while you TRUNCATE the table.

It's a general ANALYZE command for the entire DB. It's about 6GB in size,
and is vacuumed as frequently as possible; there is certainly unreclaimed
space, but it does not substantially outweigh used space. My *guess* is
that the largest table is being ANALYZEd at the time (it uses most of the
6GB), and for some reason pg_listeners is being locked in ACCESS SHARE the
entire time.

Just vacuuming pg_listener produces:

vacuum verbose pg_listener;
INFO: vacuuming "pg_catalog.pg_listener"
INFO: "pg_listener": found 0 removable, 0 nonremovable row versions in 0 pages
VACUUM

----------------------------------------------------------------
Philip Warner | __---_____
Albatross Consulting Pty. Ltd. |----/ - \
(A.B.N. 75 008 659 498) | /(@) ______---_
Tel: (+61) 0500 83 82 81 | _________ \
Fax: (+61) 03 5330 3172 | ___________ |
Http://www.rhyme.com.au | / \|
| --________--
PGP key available upon request, | /
and from pgp.mit.edu:11371 |/

On Sun, 2 May 2004, Bruce Momjian wrote:

Tom Lane wrote:

Philip Warner <pjw@rhyme.com.au> writes:

Does this mean that ANALYZE will take an exclusive lock on pg_listener
until the ANALYZE finishes? Or is there some other cause?

ANALYZE does not take an exclusive lock on anything. However, the
async.c functions want AccessExclusiveLock on pg_listener, so they
quite possibly would get blocked by ANALYZE's not-so-exclusive lock.

Possibly we could reduce the strength of the lock taken by the async.c
functions ... I haven't thought hard about it. The long-term answer is
certainly a wholesale rewrite of the listen/notify mechanism.

Gavin was working on it a while ago but I am not sure how far he got.

Its basically written.

It is implemented using shared memory. I got stuck when I considered the
situation where we rung out of shared memory. Some emails in the archive
suggested we just fire all listeners but I didn't like that.

What I was considering was that when someone issues a NOTIFY, we reserve a
slot for the NOTIFY (plus a message, which is why I originally looked at
the problem) in shared memory. At the end of the transaction, we update a
flag to say that the transaction successed or we remove it if we've
aborted.

Does anyone else have any thoughts about it?

Gavin

Philip Warner <pjw@rhyme.com.au> writes:

... for some reason pg_listeners is being locked in ACCESS SHARE the
entire time.

Just vacuuming pg_listener produces:

vacuum verbose pg_listener;
INFO: vacuuming "pg_catalog.pg_listener"
INFO: "pg_listener": found 0 removable, 0 nonremovable row versions in 0 pages
VACUUM

[blinks...] There's something pretty strange about that. Are you using
LISTEN/NOTIFY at all?

regards, tom lane

At 02:21 PM 3/05/2004, Tom Lane wrote:

[blinks...] There's something pretty strange about that. Are you using
LISTEN/NOTIFY at all?

Nope.

----------------------------------------------------------------
Philip Warner | __---_____
Albatross Consulting Pty. Ltd. |----/ - \
(A.B.N. 75 008 659 498) | /(@) ______---_
Tel: (+61) 0500 83 82 81 | _________ \
Fax: (+61) 03 5330 3172 | ___________ |
Http://www.rhyme.com.au | / \|
| --________--
PGP key available upon request, | /
and from pgp.mit.edu:11371 |/

Philip Warner <pjw@rhyme.com.au> writes:

At 02:21 PM 3/05/2004, Tom Lane wrote:

[blinks...] There's something pretty strange about that. Are you using
LISTEN/NOTIFY at all?

Nope.

In that case there's no reason for anything to be taking any particular
locks on pg_listener; and it's simply not possible for ANALYZE to spend
half an hour on a zero-page table if it's not blocked by a lock. Could
you dig a little deeper and see where the problem really is?

regards, tom lane

At 02:33 PM 3/05/2004, Tom Lane wrote:

Could
you dig a little deeper and see where the problem really is?

I thought I had 8-(.

The result of a 'select * from pg_locks where not granted' was a bunch of
locks on the pg_listener relation, and no others. Only one process had a
lock on that relation, and it was an ANALYZE command. If there is something
else to look for next time it happens, please let me know.

----------------------------------------------------------------
Philip Warner | __---_____
Albatross Consulting Pty. Ltd. |----/ - \
(A.B.N. 75 008 659 498) | /(@) ______---_
Tel: (+61) 0500 83 82 81 | _________ \
Fax: (+61) 03 5330 3172 | ___________ |
Http://www.rhyme.com.au | / \|
| --________--
PGP key available upon request, | /
and from pgp.mit.edu:11371 |/

Philip Warner <pjw@rhyme.com.au> writes:

At 02:33 PM 3/05/2004, Tom Lane wrote:

Could you dig a little deeper and see where the problem really is?

I thought I had 8-(.

The result of a 'select * from pg_locks where not granted' was a bunch of
locks on the pg_listener relation, and no others. Only one process had a
lock on that relation, and it was an ANALYZE command.

I don't believe any of this. In the first place, if you're not using
LISTEN/NOTIFY then there's no reason for any backend to try to take out
an AccessExclusive lock on pg_listener (which is the only kind that would
be blocked by ANALYZE's measly AccessShareLock). In the second place,
an ANALYZE on a zero-page relation cannot conceivably take half an hour,
unless it's in turn being blocked by something else.

Please dig deeper.

regards, tom lane

At 02:54 PM 3/05/2004, Tom Lane wrote:

I don't believe any of this.

mail=# select * from pg_locks where not granted;
relation | database | transaction | pid | mode | granted
----------+----------+-------------+-------+---------------------+---------
16414 | 17149 | | 7847 | AccessExclusiveLock | f
16414 | 17149 | | 51015 | AccessExclusiveLock | f
16414 | 17149 | | 51149 | AccessExclusiveLock | f
16414 | 17149 | | 51024 | AccessExclusiveLock | f
16414 | 17149 | | 48838 | AccessExclusiveLock | f
16414 | 17149 | | 57670 | AccessExclusiveLock | f
16414 | 17149 | | 54535 | AccessExclusiveLock | f
16414 | 17149 | | 57756 | AccessExclusiveLock | f
16414 | 17149 | | 25894 | AccessExclusiveLock | f
16414 | 17149 | | 55813 | AccessExclusiveLock | f
16414 | 17149 | | 18181 | AccessExclusiveLock | f
16414 | 17149 | | 57846 | AccessExclusiveLock | f
16414 | 17149 | | 44827 | AccessExclusiveLock | f
16414 | 17149 | | 52352 | AccessExclusiveLock | f
16414 | 17149 | | 51239 | AccessExclusiveLock | f
16414 | 17149 | | 14610 | AccessExclusiveLock | f
16414 | 17149 | | 88549 | AccessExclusiveLock | f
16414 | 17149 | | 36939 | AccessExclusiveLock | f
16414 | 17149 | | 57120 | AccessExclusiveLock | f
16414 | 17149 | | 89107 | AccessExclusiveLock | f
16414 | 17149 | | 48915 | AccessExclusiveLock | f
16414 | 17149 | | 74102 | AccessExclusiveLock | f
16414 | 17149 | | 51029 | AccessExclusiveLock | f
16414 | 17149 | | 51100 | AccessExclusiveLock | f
16414 | 17149 | | 57865 | AccessExclusiveLock | f
16414 | 17149 | | 45777 | AccessExclusiveLock | f
16414 | 17149 | | 22288 | AccessExclusiveLock | f
16414 | 17149 | | 52006 | AccessExclusiveLock | f
16414 | 17149 | | 44829 | AccessExclusiveLock | f
16414 | 17149 | | 49073 | AccessExclusiveLock | f
16414 | 17149 | | 52827 | AccessExclusiveLock | f
16414 | 17149 | | 21003 | AccessExclusiveLock | f
16414 | 17149 | | 50204 | AccessExclusiveLock | f
mail=# select * from pg_class where oid=16414;
relname | relnamespace | reltype | relowner | relam | relfilenode |
relpages | reltuples | reltoastrelid | reltoastidxid | relh
asindex | relisshared | relkind | relnatts | relchecks | reltriggers |
relukeys | relfkeys | relrefs | relhasoids | relhaspkey | rel
hasrules | relhassubclass | relacl
-------------+--------------+---------+----------+-------+-------------+----------+-----------+---------------+---------------+-----
--------+-------------+---------+----------+-----------+-------------+----------+----------+---------+------------+------------+----
---------+----------------+------------
pg_listener | 11 | 16415 | 1 | 0 | 16414
| 0 | 0 | 0 | 0 | f
| f | r | 3 | 0 | 0
| 0 | 0 | 0 | f | f | f
| f | {=r/pgsql}
(1 row)

mail=# select * from pg_locks where granted and relation=16414;
relation | database | transaction | pid | mode | granted
----------+----------+-------------+-------+-----------------+---------
16414 | 17149 | | 56399 | AccessShareLock | t
(1 row)

mail=# \q
[~] root@beast>ps ax | grep 56399;
56399 ?? D 0:03.41 postmaster: pgsql mail 127.0.0.1 ANALYZE (postgres)
[~] root@beast>kill -TERM 56399
[~] root@beast>ps ax | grep 56399;
[~] root@beast>psql -p5443 -U pgsql mail
Welcome to psql 7.3.3, the PostgreSQL interactive terminal.

Type: \copyright for distribution terms
\h for help with SQL commands
\? for help on internal slash commands
\g or terminate with semicolon to execute query
\q to quit

mail=# select * from pg_locks where granted and relation=16414;
relation | database | transaction | pid | mode | granted
----------+----------+-------------+-----+------+---------
(0 rows)

mail=# select * from pg_locks where not granted;
relation | database | transaction | pid | mode | granted
----------+----------+-------------+-------+-----------+---------
| | 65738548 | 72279 | ShareLock | f
| | 65738548 | 40479 | ShareLock | f
| | 65738548 | 46830 | ShareLock | f
| | 65738478 | 20762 | ShareLock | f
(4 rows)

mail=# select * from pg_locks where not granted;
relation | database | transaction | pid | mode | granted
----------+----------+-------------+-----+------+---------
(0 rows)

----------------------------------------------------------------
Philip Warner | __---_____
Albatross Consulting Pty. Ltd. |----/ - \
(A.B.N. 75 008 659 498) | /(@) ______---_
Tel: (+61) 0500 83 82 81 | _________ \
Fax: (+61) 03 5330 3172 | ___________ |
Http://www.rhyme.com.au | / \|
| --________--
PGP key available upon request, | /
and from pgp.mit.edu:11371 |/

At 02:54 PM 3/05/2004, Tom Lane wrote:

Please dig deeper.

I will log everything I check next time; unfortunately, when it happens,
the priority is on unlocking everything so I have a limited time to play.
So far, killing the ANALYZE has fixed the problem each time.

----------------------------------------------------------------
Philip Warner | __---_____
Albatross Consulting Pty. Ltd. |----/ - \
(A.B.N. 75 008 659 498) | /(@) ______---_
Tel: (+61) 0500 83 82 81 | _________ \
Fax: (+61) 03 5330 3172 | ___________ |
Http://www.rhyme.com.au | / \|
| --________--
PGP key available upon request, | /
and from pgp.mit.edu:11371 |/

At 02:54 PM 3/05/2004, Tom Lane wrote:

Please dig deeper.

I may have found the problem; all the hung processes show 'async_notify
waiting' in ps, and the ANALYZE eventually dies with 'tuple concurrently
updated'.

The routine 'ProcessIncomingNotify' in async.c does indeed try to lock
pg_listener (even if we're not using NOTIFY/LISTEN). Not sure why the
ANALYZE is locking the relation, though...but it is locked in AccessShareLock.

I can send a log of my investigations if necessary.

----------------------------------------------------------------
Philip Warner | __---_____
Albatross Consulting Pty. Ltd. |----/ - \
(A.B.N. 75 008 659 498) | /(@) ______---_
Tel: (+61) 0500 83 82 81 | _________ \
Fax: (+61) 03 5330 3172 | ___________ |
Http://www.rhyme.com.au | / \|
| --________--
PGP key available upon request, | /
and from pgp.mit.edu:11371 |/

Further to this, ProcessIncomingNotify seems to hold the lock on the
listener relation until it's current transaction exits. If the ANALYZE was
not the source of the error, but was just another victim, does that mean it
might hold the lock for a very long time if the analyze is lengthy?

At 02:54 PM 3/05/2004, Tom Lane wrote:

Please dig deeper.

I may have found the problem; all the hung processes show 'async_notify
waiting' in ps, and the ANALYZE eventually dies with 'tuple concurrently
updated'.

The routine 'ProcessIncomingNotify' in async.c does indeed try to lock
pg_listener (even if we're not using NOTIFY/LISTEN). Not sure why the
ANALYZE is locking the relation, though...but it is locked in AccessShareLock.

I can send a log of my investigations if necessary.

----------------------------------------------------------------
Philip Warner | __---_____
Albatross Consulting Pty. Ltd. |----/ - \
(A.B.N. 75 008 659 498) | /(@) ______---_
Tel: (+61) 0500 83 82 81 | _________ \
Fax: (+61) 03 5330 3172 | ___________ |
Http://www.rhyme.com.au | / \|
| --________--
PGP key available upon request, | /
and from pgp.mit.edu:11371 |/

At 06:21 PM 3/05/2004, Philip Warner wrote:

'tuple concurrently updated'

The database logs show the same error in each case where a long delay has
occurred. And before anyone suggests it, we already have processes in place
to prevent to ANALYZEs running at the same time.

----------------------------------------------------------------
Philip Warner | __---_____
Albatross Consulting Pty. Ltd. |----/ - \
(A.B.N. 75 008 659 498) | /(@) ______---_
Tel: (+61) 0500 83 82 81 | _________ \
Fax: (+61) 03 5330 3172 | ___________ |
Http://www.rhyme.com.au | / \|
| --________--
PGP key available upon request, | /
and from pgp.mit.edu:11371 |/

At 06:21 PM 3/05/2004, Philip Warner wrote:

'tuple concurrently updated'

I lied. The database DO NOT logs show the same error in each case where a
long delay has occurred. It happens sometimes; recent process logs do show
the 'async_notify waiting' status, however.

I'll try not to send any more emails until someone responds ;-)

----------------------------------------------------------------
Philip Warner | __---_____
Albatross Consulting Pty. Ltd. |----/ - \
(A.B.N. 75 008 659 498) | /(@) ______---_
Tel: (+61) 0500 83 82 81 | _________ \
Fax: (+61) 03 5330 3172 | ___________ |
Http://www.rhyme.com.au | / \|
| --________--
PGP key available upon request, | /
and from pgp.mit.edu:11371 |/

Philip Warner <pjw@rhyme.com.au> writes:

I may have found the problem; all the hung processes show 'async_notify
waiting' in ps, and the ANALYZE eventually dies with 'tuple concurrently
updated'.

The routine 'ProcessIncomingNotify' in async.c does indeed try to lock
pg_listener (even if we're not using NOTIFY/LISTEN). Not sure why the
ANALYZE is locking the relation, though...but it is locked in AccessShareLock.

Hm. What seems likely to have happened is that the sinval message queue
got full. We currently deal with this by sending SIGUSR2 to all
backends, which forces them through a NOTIFY-check cycle; a byproduct of
the transaction start is to read pending sinval messages. (This is
somebody's ugly quick hack from years ago; we really oughta find a less
expensive way of doing it.)

That would have left all the idle backends trying to get exclusive lock
on pg_listener, and if the ANALYZE subsequently reached pg_listener, its
share lock would queue up behind those requests.

What is not clear yet is why *all* of them are blocked. Seems something
else must have some kind of lock already on pg_listener; but who?

Can you get a dump of the pg_locks view while this is happening?

And before anyone suggests it, we already have processes in place
to prevent to ANALYZEs running at the same time.

How confident are you in those "processes"? I don't know of any other
mechanism for 'tuple concurrently updated' failures in ANALYZE than
concurrent analyze runs ...

regards, tom lane