BUG #2859: related with BUG #2568: autovacuum locks tables and do nothing

The following bug has been logged online:

Bug reference: 2859
Logged by: Harry Liu
Email address: hliu(at)mixedsignals(dot)com
PostgreSQL version: 8.1.0
Operating system: Linux sentry145.gpi.local 2.6.17-gentoo-r7-MSI #27 SMP
PREEMPT Wed Dec 6 19:22:31 PST 2006 i686 Intel(R) Pentium(R) 4 CPU 3.20GHz
GenuineIntel GNU/Lin
Description: related with BUG #2568: autovacuum locks tables and do
nothing
Details:

Hi, we encountered similar issue like bug #2568.

After autovacuum finished vacuuming two index on the table, it stops there
when try to vacuum the table itself. (appmgr_alert_log_data)

ShareUpdateExclusiveLock is granted to autovacuum for the table and two
indexes on the table (there are more indexes on that table.)

There are other process trying to access the table at the same time.
One is waiting for rowexclusive lock,
another is waiting for share lock.(in our stored procedure, we explicitly
lock the table in share mode. it is the only table get locked in that stored
procedure/transaction.)

Looks like the share lock approach messed things up (or triggered some
bug?)

Here is the content of pg_locks join with pg_class:
*************************************
transactionid | page | objid | granted | relation | transaction | pid |
mode | locktype | relname
---------------+------+-------+---------+----------+-------------+-------+--
------------------------+---------------+---------------------------------
167615582 | | | t | | 167615582 | 1809 |
ExclusiveLock | transactionid |
| | | t | 1259 | 167615582 | 1809 |
AccessShareLock | relation | pg_class
| | | t | 10342 | 167615582 | 1809 |
AccessShareLock | relation | pg_locks
| | | t | 397073 | 167612689 | 22980 |
AccessShareLock | relation | appmgr_alert_log_data_combo_idx
| | | t | 206237 | 167612689 | 22980 |
AccessShareLock | relation | svc_data
| | | t | 129912 | 167612689 | 22980 |
AccessShareLock | relation | alerts_source_info
| | | t | 129172 | 167612689 | 22980 |
AccessShareLock | relation | program_provider_mappings
| | | t | 129194 | 167612689 | 22980 |
AccessShareLock | relation | xds_data
| | | t | 129877 | 167612689 | 22980 |
AccessShareLock | relation | alerts
| | | t | 337269 | 167612689 | 22980 |
AccessShareLock | relation | super_group
| | | t | 337174 | 167612689 | 22980 |
AccessShareLock | relation | appmgr_alert_log_data
| | | f | 337174 | 167612689 | 22980 |
RowExclusiveLock | relation | appmgr_alert_log_data
| | | t | 129057 | 167612689 | 22980 |
AccessShareLock | relation | programs_pids_lookup
| | | t | 129159 | 167612689 | 22980 |
AccessShareLock | relation | providers
| | | t | 373858 | 167612689 | 22980 |
AccessShareLock | relation | alert_snapshot
| | | t | 129011 | 167612689 | 22980 |
AccessShareLock | relation | programs
| | | t | 129277 | 167612689 | 22980 |
AccessShareLock | relation | bfs_downloads
167612689 | | | t | | 167612689 | 22980 |
ExclusiveLock | transactionid |
| | | f | 337174 | 167612692 | 27793 |
ShareLock | relation | appmgr_alert_log_data
167612692 | | | t | | 167612692 | 27793 |
ExclusiveLock | transactionid |
| | | t | 373656 | 167612690 | 27794 |
ShareUpdateExclusiveLock | relation | appmgr_alert_log_data_pkey
| | | t | 337174 | 167612690 | 27794 |
ShareUpdateExclusiveLock | relation | appmgr_alert_log_data
| | | t | 397073 | 167612690 | 27794 |
ShareUpdateExclusiveLock | relation | appmgr_alert_log_data_combo_idx
167612690 | | | t | | 167612690 | 27794 |
ExclusiveLock | transactionid |
| | | f | 337174 | 167612782 | 27830 |
ShareLock | relation | appmgr_alert_log_data
167612782 | | | t | | 167612782 | 27830 |
ExclusiveLock | transactionid |
167612877 | | | t | | 167612877 | 27860 |
ExclusiveLock | transactionid |
| | | f | 337174 | 167612877 | 27860 |
ShareLock | relation | appmgr_alert_log_data
| | | f | 337174 | 167612963 | 27904 |
ShareLock | relation | appmgr_alert_log_data
167612963 | | | t | | 167612963 | 27904 |
ExclusiveLock | transactionid |
167613049 | | | t | | 167613049 | 27917 |
ExclusiveLock | transactionid |
| | | f | 337174 | 167613049 | 27917 |
ShareLock | relation | appmgr_alert_log_data
167613135 | | | t | | 167613135 | 27938 |
ExclusiveLock | transactionid |
| | | f | 337174 | 167613135 | 27938 |
ShareLock | relation | appmgr_alert_log_data
167613245 | | | t | | 167613245 | 27994 |
ExclusiveLock | transactionid |
| | | f | 337174 | 167613245 | 27994 |
ShareLock | relation | appmgr_alert_log_data
| | | f | 337174 | 167613340 | 28011 |
ShareLock | relation | appmgr_alert_log_data
167613340 | | | t | | 167613340 | 28011 |
ExclusiveLock | transactionid |
167613435 | | | t | | 167613435 | 28055 |
ExclusiveLock | transactionid |
| | | f | 337174 | 167613435 | 28055 |
ShareLock | relation | appmgr_alert_log_data

**************************************

pid 27794 is autovacuum

db log for your reference:
*******************************************
<27793:2006-12-20 22:19:03 PST>LOG: connection received: host=[local]

<27793:2006-12-20 22:19:03 PST>LOG: connection authorized: user=apache
database=previsesentry
<23175:2006-12-20 22:19:03 PST>DEBUG: forked new backend, pid=27793
socket=7
<27793:2006-12-20 22:19:03 PST>LOG: statement: SELECT session_data
FROM php_sessions WHERE session_id = '992f763fe91f1b4ebd00ab2a906a5596'
<27794:2006-12-20 22:19:03 PST>LOG: autovacuum: processing
database "previsesentry"
<27793:2006-12-20 22:19:03 PST>LOG: duration: 53.625 ms

<22980:2006-12-20 22:19:03 PST>LOG: duration: 113.043 ms

<27793:2006-12-20 22:19:03 PST>LOG: statement: SELECT *
FROM describe_table('public', 'sessions')
<22980:2006-12-20 22:19:03 PST>LOG: statement: SELECT
bw5s('1166681938','1166681943','{{4,99,0,0,1,0},{5,99,0,0,1,0},{6,99,0,0,1,0
},{7,99,0,0,1,0},{12,7121,1,1,0,0},{13,7121,1,1,0,0},{14,7121,1,1,0,0},{15,7
121,1,1,0,0},{20,99,1,1,0,0},{21,99,1,1,0,0},{22,99,1,1,0,0},{23,99,1,1,0,0}
}','{{880,0},{880,0},{880,0},{880,0},{163,0},{163,0},{163,0},{163,0}}','{{55
,2647383},{55,2647383},{55,2647383},{55,2647383},{3,864046},{3,864046},{3,86
3746},{3,864046}}','{{4094,0},{4094,0},{4094,0},{4094,0}}','{}');

<27793:2006-12-20 22:19:03 PST>LOG:
duration: 20.946 ms
<27793:2006-12-20 22:19:03 PST>LOG:
statement: SELECT id FROM public.sessions WHERE fingerprint =
'cf39274f8f19a7db6963bacc7a06e7a2' <27794:2006-12-20
22:19:03 PST>DEBUG: autovac: will VACUUM ANALYZE appmgr_alert_log_data

<27793:2006-12-20 22:19:03 PST>LOG: duration: 75.745 ms

<27793:2006-12-20 22:19:03 PST>LOG: statement: SELECT * FROM
public.sessions WHERE id='79371'::int8
<27793:2006-12-20 22:19:03 PST>LOG: duration: 0.654 ms

<27793:2006-12-20 22:19:03 PST>LOG: statement: SELECT *
FROM describe_table('public', 'users')
<22980:2006-12-20 22:19:03 PST>LOG: duration: 102.083
ms
<22980:2006-12-20 22:19:03 PST>LOG: statement:
SELECT
bfs_bitrate_5sec('1166681938','1166681943','{{24,6,1},{25,6,1},{26,6,1},{27,
6,1},{28,6,1},{29,6,1}}','{{113,2,8,0,84908},{113,2,8,0,84908},{113,2,8,0,84
908},{113,2,8,0,84908},{113,2,8,0,84908},{113,2,8,0,84908}}');
<27793:2006-12-20 22:19:03 PST>LOG: duration:
4.496 ms
<27793:2006-12-20 22:19:03 PST>LOG:
statement: SELECT * FROM public.users WHERE id='4'::int8
<27793:2006-12-20 22:19:03 PST>LOG:
duration: 1.584 ms
<27793:2006-12-20 22:19:03
PST>LOG: statement: SELECT * FROM runtime_info_view
<27793:2006-12-20
22:19:03 PST>LOG: duration: 1.480 ms

<27793:2006-12-20 22:19:03 PST>LOG: statement: SELECT * FROM
system_settings_view
<27793:2006-12-20 22:19:03 PST>LOG: duration: 2.078 ms

<27793:2006-12-20 22:19:03 PST>LOG: statement: SELECT *
FROM ports_view
<22980:2006-12-20 22:19:03 PST>LOG: duration: 19.252
ms
<22980:2006-12-20 22:19:03 PST>LOG: statement:
SELECT
tbl_bw5s('1166681938','1166681943','{{4,99,0,0,0,0,1},{5,99,0,0,0,0,1},{6,99
,0,0,0,0,1},{7,99,0,0,0,0,1},{12,7121,0,0,0,0,1},{13,7121,0,0,0,0,1},{14,712
1,0,0,0,0,1},{15,7121,0,0,0,0,1},{20,99,0,0,0,0,5},{21,99,0,0,0,0,5},{22,99,
0,0,0,0,5},{23,99,0,0,0,0,5}}','{}','{}','{}','{}','{{4094,197,0,114993},{40
94,197,0,114993},{4094,197,0,114993},{4094,197,0,114993},{880,252,0,257722},
{880,252,0,257722},{880,252,0,257722},{880,252,0,257722},{163,252,0,31808},{
4090,152,0,28168},{4094,194,2395,2052},{4094,195,0,899},{4090,197,0,95423},{
163,252,0,31808},{4090,152,0,28168},{4094,194,2395,2052},{4094,195,0,899},{4
090,197,0,95423},{163,252,0,31808},{4090,152,0,28168},{4094,194,2395,2052},{
4094,195,0,899},{4090,197,0,95423},{163,252,0,31808},{4090,152,0,28168},{409
4,194,2395,2052},{4094,195,0,899},{4090,197,0,95423}}');
<27793:2006-12-20 22:19:03 PST>LOG:
duration: 8.682 ms
<27793:2006-12-20 22:19:03 PST>LOG:
statement: SELECT * FROM appmgr_settings_view;
<27794:2006-12-20 22:19:03
PST>DEBUG: autovac: will ANALYZE port_etr_state_offline
<27794:2006-12-20
22:19:03 PST>DEBUG: autovac: will ANALYZE programs_bandwidth_1min_23935

<27794:2006-12-20 22:19:03 PST>DEBUG: autovac: will ANALYZE
transport_tables_bw_1min_23938
<27794:2006-12-20 22:19:03 PST>DEBUG: autovac: will
ANALYZE pids_bandwidth_5sec_23940
<27794:2006-12-20 22:19:03 PST>DEBUG: autovac:
will ANALYZE bfs_downloads
<27794:2006-12-20 22:19:03 PST>DEBUG:
autovac: will ANALYZE pid_state_offline
<27793:2006-12-20 22:19:03 PST>LOG:
duration: 37.176 ms
<27793:2006-12-20 22:19:03 PST>LOG:
statement: SELECT * FROM system_modules_view;
<22980:2006-12-20 22:19:03
PST>LOG: duration: 111.007 ms

<22980:2006-12-20 22:19:03 PST>LOG: statement: SELECT
alert_state('1166681943','14033','38415','6815','{{0,1061894,2642,3,600,732}
,{0,1061894,2638,2,600,732},{0,1061894,2634,1,600,732},{0,1061894,2630,0,600
,732},{1,776080,2688,7,99,1},{1,776080,2673,6,99,1},{0,1262445,2685,6,99,13}
,{0,1262445,2700,7,99,13},{1,776080,2643,4,99,1},{1,776080,2658,5,99,1},{0,1
262445,2670,5,99,13},{0,1262445,2655,4,99,13},{0,1164271,2855,23,99,12},{0,1
164571,2816,20,99,12},{0,1164271,2842,22,99,12},{0,1164571,2829,21,99,12},{0
,1059793,2852,23,99,7},{0,1060093,2813,20,99,7},{0,1060093,2826,21,99,7},{0,
1059793,2839,22,99,7}}');
<27794:2006-12-20 22:19:03 PST>DEBUG: vacuuming
"public.appmgr_alert_log_data"
<27793:2006-12-20 22:19:03 PST>LOG: duration: 89.749 ms
<27793:2006-12-20 22:19:03 PST>LOG: statement: SELECT page, script, active,
label FROM pages
<27793:2006-12-20 22:19:03 PST>LOG: duration: 1.003 ms
<27793:2006-12-20 22:19:03 PST>LOG: statement: SELECT
clear_appmgr_alert_log('{{18725808,t,f},{18725809,t,f},{18725812,t,f},{18725
813,t,f},{18725914,t,f},{18725915,t,f},{18725916,t,f},{18725917,t,f},{187259
94,t,f},{18725995,t,f},{18725996,t,f},{18725997,t,f},{18725998,t,f},{1872599
9,t,f},{18726000,t,f},{18726001,t,f},{18726002,t,f},{18726003,t,f},{18726004
,t,f},{18726005,t,f},{18726010,t,f},{18726011,t,f},{18726012,t,f},{18726013,
t,f},{18726014,f,NULL},{18726015,f,NULL},{18726016,f,NULL},{18726017,f,NULL}
,{18726018,f,NULL},{18726019,f,NULL},{18726020,f,NULL},{18726021,f,NULL},{18
726022,f,NULL},{18726023,f,NULL},{18726024,f,NULL},{18726025,f,NULL},{187260
26,f,NULL},{18726027,f,NULL},{18726028,f,NULL},{18726029,f,NULL},{18726030,f
,NULL},{18726031,f,NULL},{18726032,f,NULL},{18726033,f,NULL},{18726034,f,NUL
L},{18726035,f,NULL},{18726036,f,NULL},{18726037,f,NULL},{18726038,f,NULL},{
18726039,f,NULL},{18726040,f,NULL},{18726041,f,NULL},{18726042,f,NULL},{1872
6043,f,NULL},{18726044,f,NULL},{18726045,f,NULL},{18726046,f,NULL},{18726047
,f,NULL},{18726048,f,NULL},{18726049,f,NULL},{18726050,f,NULL},{18726051,f,N
ULL},{18726052,f,NULL},{18726053,f,NULL},{18726054,f,NULL},{18726055,f,NULL}
,{18726056,f,NULL},{18726057,f,NULL},{18726058,f,NULL},{18726059,f,NULL},{18
726060,f,NULL},{18726061,f,NULL},{18726062,f,NULL},{18726063,f,NULL},{187260
64,f,NULL},{18726065,f,NULL},{18726066,f,NULL},{18726067,f,NULL},{18726068,f
,NULL},{18726069,f,NULL},{18726070,f,NULL},{18726071,f,NULL},{18726072,f,NUL
L},{18726073,f,NULL},{18726074,f,NULL},{18726075,f,NULL},{18726076,f,NULL},{
18726077,f,NULL},{18726078,f,f},{18726079,f,f},{18726080,f,f},{18726081,f,f}
,{18726082,f,f},{18726083,f,f},{18726084,f,f},{18726085,f,f},{18726086,f,NUL
L},{18726087,f,NULL},{18726088,f,NULL},{18726089,f,NULL},{18726090,f,f},{187
26091,f,f},{18726092,f,f},{18726093,f,f},{18726094,f,f},{18726095,f,f},{1872
6096,f,f},{18726097,f,f},{18726098,f,NULL},{18726099,f,NULL},{18726100,f,NUL
L},{18726101,f,NULL},{18726102,f,f},{18726103,f,f},{18726104,f,f},{18726105,
f,f},{18726106,f,NULL},{18726107,f,NULL},{18726108,f,NULL},{18726109,f,NULL}
,{18726110,f,NULL},{18726111,f,NULL},{18726112,f,NULL},{18726113,f,NULL},{18
726114,f,NULL},{18726115,f,NULL},{18726116,f,NULL},{18726117,f,NULL},{187261
18,f,NULL},{18726119,f,NULL},{18726120,f,NULL},{18726121,f,NULL},{18726122,f
,NULL},{18726123,f,NULL},{18726124,f,NULL},{18726125,f,NULL},{18726126,f,NUL
L},{18726127,f,NULL},{18726128,f,NULL},{18726129,f,NULL},{18726130,f,NULL},{
18726131,f,NULL},{18726132,f,NULL},{18726133,f,NULL},{18726134,f,NULL},{1872
6135,f,NULL},{18726136,f,NULL},{18726137,f,NULL},{18726138,f,NULL},{18726139
,f,NULL},{18726140,f,NULL},{18726141,f,NULL},{18726142,f,NULL},{18726143,f,N
ULL},{18726144,f,NULL},{18726145,f,NULL},{18726146,f,NULL},{18726147,f,NULL}
,{18726148,f,NULL},{18726149,f,NULL},{18726150,f,NULL},{18726151,f,NULL},{18
726152,f,NULL},{18726153,f,NULL},{18726154,f,NULL},{18726155,f,NULL},{187261
56,f,NULL},{18726157,f,NULL},{18726158,f,NULL},{18726159,f,NULL},{18726160,f
,NULL},{18726161,f,NULL},{18726162,f,NULL},{18726163,f,NULL},{18726164,f,NUL
L},{18726165,f,NULL},{18726166,f,NULL},{18726167,f,NULL},{18726168,f,NULL},{
18726169,f,NULL},{18726170,f,NULL},{18726171,f,NULL},{18726172,f,NULL},{1872
6173,f,NULL},{18726174,f,NULL},{18726175,f,NULL},{18726176,f,f},{18726177,f,
f},{18726178,f,NULL},{18726179,f,NULL},{18726180,f,f},{18726181,f,f},{187261
82,f,f},{18726183,f,f},{18726184,f,f},{18726185,f,f},{18726186,f,f},{1872618
7,f,f},{18726188,f,f},{18726189,f,f}}',0);
<27794:2006-12-20 22:19:03 PST>DEBUG: index "appmgr_alert_log_data_pkey"
now contains 495 row versions in 866 pages
<27794:2006-12-20 22:19:03 PST>DETAIL: 3236 index row versions were
removed.
843 index pages have been deleted, 838 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
<27794:2006-12-20 22:19:04 PST>DEBUG: index
"appmgr_alert_log_data_combo_idx" now contains 235 row versions in 21 pages
<27794:2006-12-20 22:19:04 PST>DETAIL: 642 index row versions were
removed.
3 index pages have been deleted, 3 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.20 sec.
<27817:2006-12-20 22:20:01 PST>LOG: connection received: host=[local]
<27817:2006-12-20 22:20:01 PST>LOG: connection authorized: user=postgres
database=previsesentry
<23175:2006-12-20 22:20:01 PST>DEBUG: forked new backend, pid=27817
socket=7
<27817:2006-12-20 22:20:01 PST>LOG: statement: select CASE WHEN
use_absolute_limit THEN 62283 - disk_free_mb_limit ELSE (62283 *
(db_pct_size_limit/100))::int END as db_mb_limit from
system_truncate_settings order by id desc limit 1;
<27817:2006-12-20 22:20:01 PST>LOG: duration: 27.859 ms
<27817:2006-12-20 22:20:01 PST>LOG: disconnection: session time: 0:00:00.03
user=postgres database=previsesentry host=[local]
<23175:2006-12-20 22:20:01 PST>DEBUG: server process (PID 27817) exited
with exit code 0
<27820:2006-12-20 22:20:01 PST>LOG: connection received: host=[local]
<23175:2006-12-20 22:20:01 PST>DEBUG: forked new backend, pid=27820
socket=7
<27820:2006-12-20 22:20:01 PST>LOG: connection authorized: user=postgres
database=previsesentry
<27820:2006-12-20 22:20:01 PST>LOG: statement: select
delete_range_tables();
*********************************

inside the log,
pid 22980 was always there, that's our intension.
it called function alert_state which need rowexclusive lock for
appmgr_alert_log_data.
pid 27793 called function clear_appmgr_alert_log_data, which is trying to
lock appmgr_alert_log_data in share mode.

appmgr_alert_log_data has been inserted/updated/deleted a lot. Several
thousand records will be inserted/updated/deleted every minute, and it has
been like this for weeks.

The database files are not corrupted, we can successfully do other things
not need conflick lock on appmgr_alert_log_data under this lock situation.
Also, after shut down and restart postgres, all tables and content are
fine.

Let me know if you need more information.

Thanks,

Harry Liu