Обсуждение: 7.4Beta1 hang?
I appear to have a hang on my system (40 minutes so far, it's now
17:40). The code is from CVS updated 8/6 if I remember correctly.
The machine is idle, with a vacuum waiting and an INSERT doing nothing.
The vacuum is being generated via pg_autovacuum.
The output from the perl script leading up to the hang is:
2755/kir_27551925.fits.apm... 1775 stars imported 3421 per second
2755/kvr_27551925.fits.apm... 1219 stars imported 4639 per second
.....Kept 925 (75.9%) pairs of stars at 249.9 per second ( 3.7)
2755/kir_27551989.fits.apm... 1727 stars imported 3564 per second
2755/kvr_27551989.fits.apm... 918 stars imported 3518 per second
.....Kept 694 (75.6%) pairs of stars at 635.3 per second ( 1.1)
2755/kir_27552015.fits.apm... 1817 stars imported 4549 per second
2755/kvr_27552015.fits.apm... 958 stars imported 4197 per second
....
As you this shows, the insert that is hung is part of a series of
operaqtions which usually completes in under 4 seconds.
The insert is:
INSERT INTO obs_i
SELECT *
FROM temp_obs_i
WHERE obs_id IN (SELECT i_obs_id FROM obs_keep)
The PostgreSQL processes:
postgres 32242 1 0 Aug07 ? 00:00:01
/usr/local/pgsql/bin/postmaster -D /var/lib/pgsql/data postgres 32246
32242 0 Aug07 ? 00:02:38 postgres: stats buffer process
postgres 32247 32246 0 Aug07 ? 00:02:30
postgres: stats collector process
postgres 6426 32242 32 16:36 ? 00:09:21
postgres: robert tassiv 192.168.0.250 INSERT
postgres 6427 32242 1 16:36 ? 00:00:21
postgres: robert tassiv 192.168.0.250 idle
postgres 6615 32242 3 16:48 ? 00:00:34
postgres: robert tassiv localhost VACUUM waiting
postgres 6824 32242 0 17:01 ? 00:00:00
postgres: checkpoint subprocess
Anything to look at before I kick it? It's not built with debug, but I
can still get a backtrace.
Tables:
obs_keep is a temp table generated via perl script
SELECT i.obs_id AS i_obs_id, v.obs_id AS v_obs_id
INTO TEMP obs_keep
FROM (SELECT obs_id, file_id, loc FROM temp_obs_v NATURAL JOIN files WHERE group_id = $group_id
AND pair_id = $pair_id) AS v, (SELECT obs_id, file_id, loc FROM temp_obs_i NATURAL JOIN files WHERE group_id =
$group_id AND pair_id = $pair_id) AS i
WHERE i.loc @ scircle( v.loc, $MATCH_RADIUS )
tassiv=# \d temp_obs_i Table "public.temp_obs_i"Column | Type | Modifiers
---------+---------+------------------------------------------------x | real | not nully | real | not
nullimag | real | not nullsmag | real | not nullloc | spoint | not nullobs_id | integer | not null
defaultnextval('"obs_id_seq"'::text)file_id | integer | not nulluse | boolean | default falsesolve | boolean |
defaultfalsestar_id | integer | mag | real |
Indexes: "temp_obs_i_file_id_index" btree (file_id) "temp_obs_i_index" gist (loc) "temp_obs_i_loc_index" gist
(loc) "temp_obs_i_obs_id_index" btree (obs_id)
Foreign-key constraints: "temp_obs_i_files_constraint" FOREIGN KEY (file_id) REFERENCES
files(file_id) ON DELETE CASCADE Inherits: obs_root
tassiv=# \d obs_i Table "public.obs_i"Column | Type | Modifiers
---------+---------+------------------------------------------------x | real | not nully | real | not
nullimag | real | not nullsmag | real | not nullloc | spoint | not nullobs_id | integer | not null
defaultnextval('"obs_id_seq"'::text)file_id | integer | not nulluse | boolean | default falsesolve | boolean |
defaultfalsestar_id | integer | mag | real |
Indexes: "obs_i_file_id_index" btree (file_id) "obs_i_loc_index" gist (loc) "obs_i_obs_id_index" btree (obs_id)
"obs_i_star_id_index"btree (star_id) "obs_i_use_index" btree (use)
Foreign-key constraints: "obs_i_files_constraint" FOREIGN KEY (file_id) REFERENCES
files(file_id) ON DELETE CASCADE "obs_i_star_id_constraint" FOREIGN
KEY (star_id) REFERENCES catalog(star_id) ON DELETE SET NULL Triggers: obs_i_trig BEFORE INSERT OR DELETE OR UPDATE
ONobs_i FOR EACH ROW
EXECUTE PROCEDURE observations_trigger()
Inherits: obs_root
-- 17:05:52 up 8 days, 9:51, 4 users, load average: 0.03, 0.51, 0.92
Robert Creager <Robert_Creager@LogicalChaos.org> writes:
> Anything to look at before I kick it?
pg_locks and pg_stat_activity, if you can select from them in a non-stuck
backend.
> It's not built with debug, but I
> can still get a backtrace.
Might be useful.
regards, tom lane
Robert Creager <Robert_Creager@LogicalChaos.org> writes:
> [much data]
Well, I'm baffled. The vacuum process is evidently waiting for the
insert, but I don't think it could be holding any lock that the other
two want. The insert is trying to grab a per-buffer lock, which is
reasonable. I do not see that the VACUUM could have that lock, but
it's possible the checkpoint process does. However, as best I can
tell the checkpoint process is trying to get the BufMgrLock, and
neither of the other two can be holding that. So what the heck is
blocking the checkpoint?
A point of interest is that the VACUUM is trying to get the lock on a
GIST index (it must be so, as lazy_vacuum_index would not need to get
any lock at all on btree indexes). OTOH, the insert is busy trying to
insert into one of the btree indexes on obs_i (can't tell which); and
furthermore it's trying to do a page split in that index, which is
relatively uncommon. It's possible that the combination of these events
would reproducibly yield the hang, though I sure don't see how.
Could you supply the relation names corresponding to the relation OIDs
appearing in pg_locks, so we can be sure who's processing what?
After that, we've probably got all the info we can get from this
occurrence. Please rebuild with debugging enabled, and hope that
it happens again so we can get more data.
regards, tom lane
On Sat, 09 Aug 2003 21:17:05 -0400 Tom Lane <tgl@sss.pgh.pa.us> said something like: > > Could you supply the relation names corresponding to the relation OIDs > appearing in pg_locks, so we can be sure who's processing what? > Sure, if you tell me how ;-) I looked at the view definition and that didn't help me much... -- 19:32:24 up 8 days, 12:18, 4 users, load average: 2.07, 2.05, 2.00
On Sat, 09 Aug 2003 20:12:36 -0400
Tom Lane <tgl@sss.pgh.pa.us> said something like:
> Robert Creager <Robert_Creager@LogicalChaos.org> writes:
> > Anything to look at before I kick it?
>
> pg_locks and pg_stat_activity, if you can select from them in a
> non-stuck backend.
tassiv=# select * from pg_locks;relation | database | transaction | pid | mode | granted
----------+----------+-------------+------+--------------------------+--------- 17846 | 17140 | | 6426
|AccessShareLock | t 17846 | 17140 | | 6426 | RowShareLock | t 17846 | 17140
| | 6426 | RowExclusiveLock | t 17835 | 17140 | | 6426 | AccessShareLock |
t 17835 | 17140 | | 6426 | RowShareLock | t 18096 | 17140 | | 6426 |
AccessExclusiveLock | t 18045 | 17140 | | 6426 | AccessShareLock | t 18045 | 17140 |
| 6426 | RowExclusiveLock | t34527020 | 17140 | | 6426 | ShareLock |
t34527020| 17140 | | 6426 | AccessExclusiveLock | t 18015 | 17140 | | 6615 |
ShareUpdateExclusiveLock| t 17971 | 17140 | | 6426 | AccessShareLock | t 17971 | 17140 |
| 6426 | RowExclusiveLock | t 16759 | 17140 | | 8069 | AccessShareLock |
t34526324| 17140 | | 6426 | AccessShareLock | t34526324 | 17140 | | 6426 |
ShareLock | t34526324 | 17140 | | 6426 | AccessExclusiveLock | t 18101 | 17140 |
| 6426 | ShareLock | t 18101 | 17140 | | 6426 | AccessExclusiveLock | t
18096 | 17140 | | 6615 | AccessExclusiveLock | f 18028 | 17140 | | 6426 |
AccessShareLock | t 18028 | 17140 | | 6426 | RowExclusiveLock | t 18028 | 17140 |
| 6426 | ShareLock | t 18028 | 17140 | | 6426 | AccessExclusiveLock | t
17879 | 17140 | | 6426 | AccessShareLock | t 17879 | 17140 | | 6426 |
RowExclusiveLock | t | | 79764 | 8069 | ExclusiveLock | t 18015 | 17140 |
| 6426 | AccessShareLock | t 18015 | 17140 | | 6426 | RowExclusiveLock | t
| | 79690 | 6615 | ExclusiveLock | t 17855 | 17140 | | 6426 |
AccessShareLock | t 17857 | 17140 | | 6426 | AccessShareLock | t 17857 | 17140 |
| 6426 | RowShareLock | t 17857 | 17140 | | 6426 | RowExclusiveLock | t
18099 | 17140 | | 6426 | ShareLock | t 18099 | 17140 | | 6426 |
AccessExclusiveLock | t 17912 | 17140 | | 6426 | AccessShareLock | t | |
79712 | 6426 | ExclusiveLock | t 17984 | 17140 | | 6426 | AccessShareLock | t
17984 | 17140 | | 6426 | RowExclusiveLock | t 17984 | 17140 | | 6426 |
ShareLock | t 17984 | 17140 | | 6426 | AccessExclusiveLock | t 17844 | 17140 |
| 6426 | AccessShareLock | t34527019 | 17140 | | 6426 | ShareLock |
t34527019| 17140 | | 6426 | AccessExclusiveLock | t 18015 | 17140 | | 6615 |
ShareUpdateExclusiveLock| t
tassiv=# select * from pg_stat_activity;datid | datname | procpid | usesysid | usename | current_query | query_start
-------+---------+---------+----------+---------+---------------+-------------17140 | tassiv | 8069 | 100 |
robert | | 17140 | tassiv | 6426 | 100 | robert | | 17140 | tassiv | 6427 |
100 | robert | | 17140 | tassiv | 6615 | 100 | robert | |
>
> > It's not built with debug, but I
> > can still get a backtrace.
>
> Might be useful.
>
> regards, tom lane
>
>
00:00:01 /usr/local/pgsql/bin/postmaster -D /var/lib/pgsql/data
#0 0x4031fec2 in select () from /lib/i686/libc.so.6
#1 0xbffff368 in ?? ()
#2 0x081340bd in PostmasterMain ()
#3 0x08109edc in main ()
#4 0x4025e7f7 in __libc_start_main () from /lib/i686/libc.so.6
postgres: robert tassiv 192.168.0.250 INSERT
(gdb) backtrace
#0 0x403279d7 in semop () from /lib/i686/libc.so.6
#1 0x08133151 in PGSemaphoreLock ()
#2 0x081517cc in LWLockAcquire ()
#3 0x081482fd in LockBuffer ()
#4 0x0808439f in _bt_getbuf ()
#5 0x080827e4 in _bt_split ()
#6 0x08082202 in _bt_insertonpg ()
#7 0x08081ce8 in _bt_doinsert ()
#8 0x080857ea in btinsert ()
#9 0x081b77df in OidFunctionCall6 ()
#10 0x08081190 in index_insert ()
#11 0x080f75f4 in ExecInsertIndexTuples ()
#12 0x080f2034 in ExecInsert ()
#13 0x080f1d08 in ExecutePlan ()
#14 0x080f1059 in ExecutorRun ()
#15 0x08157eec in ProcessQuery ()
#16 0x08158859 in PortalRunMulti ()
#17 0x081582de in PortalRun ()
#18 0x081555ec in exec_simple_query ()
#19 0x08157602 in PostgresMain ()
#20 0x081362e8 in BackendFork ()
#21 0x08135da3 in BackendStartup ()
#22 0x081346cd in ServerLoop ()
#23 0x081340bd in PostmasterMain ()
#24 0x08109edc in main ()
#25 0x4025e7f7 in __libc_start_main () from /lib/i686/libc.so.6
00:02:38 postgres: stats buffer process
#0 0x4031fec2 in select () from /lib/i686/libc.so.6
#1 0x00000005 in ?? ()
#2 0x08138376 in pgstat_main ()
#3 0x0813711e in pgstat_start ()
#4 0x08134093 in PostmasterMain ()
#5 0x08109edc in main ()
#6 0x4025e7f7 in __libc_start_main () from /lib/i686/libc.so.6
00:02:30 postgres: stats collector process
#0 0x4031fec2 in select () from /lib/i686/libc.so.6
#1 0xbfffefb0 in ?? ()
#2 0x0813711e in pgstat_start ()
#3 0x08134093 in PostmasterMain ()
#4 0x08109edc in main ()
#5 0x4025e7f7 in __libc_start_main () from /lib/i686/libc.so.6
00:00:00 postgres: checkpoint subprocess
#0 0x403279d7 in semop () from /lib/i686/libc.so.6
#1 0x08133151 in PGSemaphoreLock ()
#2 0x081517cc in LWLockAcquire ()
#3 0x08147454 in BufferSync ()
#4 0x0814785a in FlushBufferPool ()
#5 0x08095007 in CreateCheckPoint ()
#6 0x0809900a in BootstrapMain ()
#7 0x08136a69 in SSDataBase ()
#8 0x08134797 in ServerLoop ()
#9 0x081340bd in PostmasterMain ()
#10 0x08109edc in main ()
#11 0x4025e7f7 in __libc_start_main () from /lib/i686/libc.so.6
00:00:34 postgres: robert tassiv localhost VACUUM waiting
#0 0x403279d7 in semop () from /lib/i686/libc.so.6
#1 0x08133151 in PGSemaphoreLock ()
#2 0x0815034c in ProcSleep ()
#3 0x0814f2a4 in WaitOnLock ()
#4 0x0814eeb9 in LockAcquire ()
#5 0x0814e4a9 in LockRelation ()
#6 0x080edf72 in lazy_vacuum_index ()
#7 0x080ed6e3 in lazy_scan_heap ()
#8 0x080ed347 in lazy_vacuum_rel ()
#9 0x080e99c4 in vacuum_rel ()
#10 0x080e91e1 in vacuum ()
#11 0x08158752 in PortalRunUtility ()
#12 0x081589a8 in PortalRunMulti ()
#13 0x081582de in PortalRun ()
#14 0x081555ec in exec_simple_query ()
#15 0x08157602 in PostgresMain ()
#16 0x081362e8 in BackendFork ()
#17 0x08135da3 in BackendStartup ()
#18 0x081346cd in ServerLoop ()
#19 0x081340bd in PostmasterMain ()
#20 0x08109edc in main ()
#21 0x4025e7f7 in __libc_start_main () from /lib/i686/libc.so.6
-- 18:23:04 up 8 days, 11:08, 4 users, load average: 2.04, 2.02, 1.55
Robert Creager <Robert_Creager@LogicalChaos.org> writes:
>> Could you supply the relation names corresponding to the relation OIDs
>> appearing in pg_locks, so we can be sure who's processing what?
> Sure, if you tell me how ;-) I looked at the view definition and that didn't help me much...
select relname from pg_class where oid = 'whatever';
or if you still have the pg_locks data
select relname,pg_locks.* from pg_locks,pg_class where pg_class.oid = relation;
regards, tom lane
On Sat, 09 Aug 2003 21:17:05 -0400 Tom Lane <tgl@sss.pgh.pa.us> said something like: > Robert Creager <Robert_Creager@LogicalChaos.org> writes: > > [much data] > > Could you supply the relation names corresponding to the relation OIDs > appearing in pg_locks, so we can be sure who's processing what? > Well, there appears to be a mail problem. Not sure if it's on my end, or somewhere else. I dug around a little and I might have what you asked for. The relname looks correct for what's currently being processed, but I don't know why some of the relation wouldn't have a name. Of course, I made this up, so it may be verrrry wrong... tassiv=# select relation, mode, relname from pg_locks left join pg_class on ( pg_locks.relation = pg_class.relfilenode );relation | mode | relname ----------+--------------------------+------------------- 1259 | AccessShareLock | pg_class 16759 | AccessShareLock | pg_locks 17835 | AccessShareLock | groups 17835 | RowShareLock | groups 17844 | AccessShareLock | pairs_pair_id_seq 17846 | AccessShareLock | pairs 17846 | RowShareLock | pairs 17846 | RowExclusiveLock | pairs 17855 | AccessShareLock | files_file_id_seq 17857 | AccessShareLock | files 17857 | RowShareLock | files 17857 | RowExclusiveLock | files 17879 | AccessShareLock | fits 17879 | RowExclusiveLock | fits 17912| AccessShareLock | obs_id_seq 17971 | AccessShareLock | obs_v 17971 | RowExclusiveLock | obs_v 17984 | AccessShareLock | temp_obs_v 17984 | RowExclusiveLock | temp_obs_v 17984 | ShareLock | temp_obs_v 17984 | AccessExclusiveLock | temp_obs_v 18015 | ShareUpdateExclusiveLock |obs_i 18015 | AccessShareLock | obs_i 18015 | RowExclusiveLock | obs_i 18015 | ShareUpdateExclusiveLock| obs_i 18028 | AccessShareLock | temp_obs_i 18028 | RowExclusiveLock | temp_obs_i 18028 | ShareLock | temp_obs_i 18028 | AccessExclusiveLock | temp_obs_i 18045 | AccessShareLock | imported 18045 | RowExclusiveLock | imported 18096 | AccessExclusiveLock | obs_i_loc_index 18096 | AccessExclusiveLock | obs_i_loc_index 18099 | ShareLock | 18099 | AccessExclusiveLock | 18101 | ShareLock | 18101 | AccessExclusiveLock | 34526324 | AccessShareLock | 34526324 | ShareLock | 34526324 | AccessExclusiveLock | 34527019 | ShareLock | 34527019 | AccessExclusiveLock | 34527020 | ShareLock | 34527020 | AccessExclusiveLock | | ExclusiveLock | | ExclusiveLock | | ExclusiveLock | -- 09:02:24 up 9 days, 1:47, 4 users, load average: 2.01, 2.03, 2.00
On Sat, 9 Aug 2003 17:48:38 -0600
Robert Creager <Robert_Creager@logicalchaos.org> said something like:
I received another hang, this time without a vacuum occurring. It occurred during a copy operation. While there is a
checkpointprocess running, I don't believe it was there at the start of the hang, but I'm not sure.
I did a <make distclean> before configure/make for this install.
Here is the info you asked for last time.
tassiv=# select relname, pg_locks.* from pg_locks left join pg_class on ( pg_locks.relation = pg_class.relfilenode );
relname | relation | database | transaction | pid | mode | granted
-------------------+----------+----------+-------------+-------+---------------------+---------pg_class |
1259| 17140 | | 12804 | AccessShareLock | tpg_locks | 16759 | 17140 | |
12804| AccessShareLock | tgroups | 17835 | 17140 | | 12671 | AccessShareLock |
tgroups | 17835 | 17140 | | 12671 | RowShareLock | tpairs_pair_id_seq | 17844 |
17140 | | 12671 | AccessShareLock | tpairs | 17846 | 17140 | | 12671 |
AccessShareLock | tpairs | 17846 | 17140 | | 12671 | RowShareLock | tpairs
| 17846 | 17140 | | 12671 | RowExclusiveLock | tfiles_file_id_seq | 17855 | 17140 |
| 12671 | AccessShareLock | tfiles | 17857 | 17140 | | 12671 |
AccessShareLock | tfiles | 17857 | 17140 | | 12671 | RowShareLock | tfiles
| 17857 | 17140 | | 12671 | RowExclusiveLock | tfits | 17879 | 17140 |
| 12671 | AccessShareLock | tfits | 17879 | 17140 | | 12671 |
RowExclusiveLock | tobs_id_seq | 17912 | 17140 | | 12671 | AccessShareLock | ttemp_obs_i
| 18028 | 17140 | | 12671 | RowExclusiveLock | timported | 18045 | 17140 |
| 12671 | AccessShareLock | timported | 18045 | 17140 | | 12671 |
RowExclusiveLock | t | 18101 | 17140 | | 12671 | AccessExclusiveLock | t
| 3021077 | 17140 | | 12671 | AccessExclusiveLock | t | | |
80133 | 12671 | ExclusiveLock | t | | | 80147 | 12804 | ExclusiveLock
| t
tassiv=# select * from pg_stat_activity;datid | datname | procpid | usesysid | usename | current_query | query_start
-------+---------+---------+----------+---------+---------------+-------------17140 | tassiv | 12671 | 100 |
robert | | 17140 | tassiv | 12672 | 100 | robert | | 17140 | tassiv | 12976 |
100 | robert | |
Here are the backtraces. I've build under debug and have ddd ready to go...
postgres: stats collector process
#0 0x4031fec2 in select () from /lib/i686/libc.so.6
#1 0xbfffefb0 in ?? ()
#2 0x0813711e in pgstat_start () at pgstat.c:402
#3 0x08134093 in PostmasterMain (argc=3, argv=0x82861f8) at postmaster.c:871
#4 0x08109edc in main (argc=3, argv=0xbffff954) at main.c:215
#5 0x4025e7f7 in __libc_start_main () from /lib/i686/libc.so.6
postgres: stats buffer process
(gdb) backtrace
#0 0x4031fec2 in select () from /lib/i686/libc.so.6
#1 0x00000005 in ?? ()
#2 0x08138376 in pgstat_main () at pgstat.c:1279
#3 0x0813711e in pgstat_start () at pgstat.c:402
#4 0x08134093 in PostmasterMain (argc=3, argv=0x82861f8) at postmaster.c:871
#5 0x08109edc in main (argc=3, argv=0xbffff954) at main.c:215
#6 0x4025e7f7 in __libc_start_main () from /lib/i686/libc.so.6
postgres: robert tassiv 192.168.0.250 COPY
(gdb) backtrace
#0 0x403279d7 in semop () from /lib/i686/libc.so.6
#1 0x08133151 in PGSemaphoreLock (sema=0x0, interruptOK=1 '\001') at pg_sema.c:419
#2 0x081517cc in LWLockAcquire (lockid=11097, mode=LW_EXCLUSIVE) at lwlock.c:312
#3 0x081482fd in LockBuffer (buffer=1, mode=2) at bufmgr.c:1925
#4 0x0808439f in _bt_getbuf (rel=0x457767d8, blkno=4294967292, access=2) at nbtpage.c:419
#5 0x080827e4 in _bt_split (rel=0x457767d8, buf=5538, firstright=330, newitemoff=510, newitemsz=12,
newitem=0x82fadb8,newitemonleft=0 '\0', itup_off=0xbfffe2fe, itup_blkno=0xbfffe300) at nbtinsert.c:675
#6 0x08082202 in _bt_insertonpg (rel=0x457767d8, buf=5538, stack=0x8316fa0, keysz=1, scankey=0x8316ff0,
btitem=0x82fadb8,afteritem=0, split_only_page=0 '\0') at nbtinsert.c:492
#7 0x08081ce8 in _bt_doinsert (rel=0x457767d8, btitem=0x82fadb8, index_is_unique=0 '\0', heapRel=0x456fc898) at
nbtinsert.c:141
#8 0x080857ea in btinsert (fcinfo=0xfffffffc) at nbtree.c:263
#9 0x081b77df in OidFunctionCall6 (functionId=331, arg1=4294967292, arg2=4294967292, arg3=4294967292,
arg4=4294967292,arg5=4294967292, arg6=4294967292) at fmgr.c:1345
#10 0x08081190 in index_insert (indexRelation=0x457767d8, datums=0xbfffe5b0, nulls=0xbfffe590 " \004",
heap_t_ctid=0x840f494,heapRelation=0x456fc898, check_uniqueness=0 '\0') at indexam.c:226
#11 0x080f75f4 in ExecInsertIndexTuples (slot=0x0, tupleid=0x840f494, estate=0x834a730, is_vacuum=0 '\0') at
execUtils.c:860
#12 0x080cb178 in CopyFrom (rel=0x456fc898, attnumlist=0x836dcf0, binary=0 '\0', oids=0 '\0', delim=0x8238f5a "\t",
null_print=0x820ef58 "\\N") at copy.c:1598
#13 0x080c9d38 in DoCopy (stmt=0x1) at copy.c:830
#14 0x08158752 in PortalRunUtility (portal=0x82eae40, query=0x82e5e28, dest=0x82e5cd8, completionTag=0xbfffe950 "")
atpquery.c:757
#15 0x081589a8 in PortalRunMulti (portal=0x82eae40, dest=0x82e5cd8, altdest=0x82e5cd8, completionTag=0xbfffe950 "")
atpquery.c:821
#16 0x081582de in PortalRun (portal=0x82eae40, count=2147483647, dest=0x82e5cd8, altdest=0x82e5cd8,
completionTag=0xbfffe950"") at pquery.c:483
#17 0x081555ec in exec_simple_query ( query_string=0x82e5ac8 "COPY temp_obs_I FROM stdin") at
postgres.c:875
#18 0x08157602 in PostgresMain (argc=4, argv=0x8287678, username=0x8287648 "robert") at postgres.c:2850
#19 0x081362e8 in BackendFork (port=0x82941c0) at postmaster.c:2536
#20 0x08135da3 in BackendStartup (port=0x82941c0) at postmaster.c:2184
#21 0x081346cd in ServerLoop () at postmaster.c:1108
#22 0x081340bd in PostmasterMain (argc=3, argv=0x82861f8) at postmaster.c:886
#23 0x08109edc in main (argc=3, argv=0xbffff954) at main.c:215
#24 0x4025e7f7 in __libc_start_main () from /lib/i686/libc.so.6
postgres: checkpoint subprocess
#0 0x403279d7 in semop () from /lib/i686/libc.so.6
#1 0x08133151 in PGSemaphoreLock (sema=0x0, interruptOK=1 '\001') at pg_sema.c:419
#2 0x081517cc in LWLockAcquire (lockid=11097, mode=LW_SHARED) at lwlock.c:312
#3 0x08147454 in BufferSync () at bufmgr.c:786
#4 0x0814785a in FlushBufferPool () at bufmgr.c:990
#5 0x08095007 in CreateCheckPoint (shutdown=0 '\0', force=0 '\0') at xlog.c:3282
#6 0x0809900a in BootstrapMain (argc=0, argv=0x16) at bootstrap.c:445
#7 0x08136a69 in SSDataBase (xlop=3) at postmaster.c:2842
#8 0x08134797 in ServerLoop () at postmaster.c:1039
#9 0x081340bd in PostmasterMain (argc=3, argv=0x82861f8) at postmaster.c:886
#10 0x08109edc in main (argc=3, argv=0xbffff954) at main.c:215
#11 0x4025e7f7 in __libc_start_main () from /lib/i686/libc.so.6
-- 10:11:47 up 9 days, 2:57, 4 users, load average: 0.11, 0.41, 0.96
>> What is the index temp_obs_i_obs_id_index on, exactly? Is it a serial
>> column or some such?
> Yup:
Okay, that explains it then. In a serial column's index, essentially
all splits will be on the rightmost page of the tree. This means that
when bt_split tries to get a new free page, it will almost always be
holding lock on the most recently acquired free page (since that was
the righthand side of the previous split). That's the factor that makes
the coincidence likely. A vacuum running concurrently with a page split
may mistakenly place a just-used page back into FSM (if the page gets
used between the time vacuum examines it and the time vacuum finishes
and loads its results into FSM). So if that happens, and said page is
the first to be returned by FSM for the next split, you lose.
I've committed the attached fix.
regards, tom lane
*** src/backend/access/nbtree/nbtpage.c.orig Fri Aug 8 17:47:01 2003
--- src/backend/access/nbtree/nbtpage.c Sun Aug 10 15:32:16 2003
***************
*** 409,414 ****
--- 409,430 ---- * that the page is still free. (For example, an already-free * page could have been
re-usedbetween the time the last VACUUM * scanned it and the time the VACUUM made its FSM updates.)
+ *
+ * In fact, it's worse than that: we can't even assume that it's
+ * safe to take a lock on the reported page. If somebody else
+ * has a lock on it, or even worse our own caller does, we could
+ * deadlock. (The own-caller scenario is actually not improbable.
+ * Consider an index on a serial or timestamp column. Nearly all
+ * splits will be at the rightmost page, so it's entirely likely
+ * that _bt_split will call us while holding a lock on the page most
+ * recently acquired from FSM. A VACUUM running concurrently with
+ * the previous split could well have placed that page back in FSM.)
+ *
+ * To get around that, we ask for only a conditional lock on the
+ * reported page. If we fail, then someone else is using the page,
+ * and we may reasonably assume it's not free. (If we happen to be
+ * wrong, the worst consequence is the page will be lost to use till
+ * the next VACUUM, which is no big problem.) */ for (;;) {
***************
*** 416,431 **** if (blkno == InvalidBlockNumber) break; buf = ReadBuffer(rel,
blkno);
! LockBuffer(buf, access);
! page = BufferGetPage(buf);
! if (_bt_page_recyclable(page)) {
! /* Okay to use page. Re-initialize and return it */
! _bt_pageinit(page, BufferGetPageSize(buf));
! return buf; }
- elog(DEBUG2, "FSM returned nonrecyclable page");
- _bt_relbuf(rel, buf); } /*
--- 432,455 ---- if (blkno == InvalidBlockNumber) break; buf = ReadBuffer(rel,
blkno);
! if (ConditionalLockBuffer(buf)) {
! page = BufferGetPage(buf);
! if (_bt_page_recyclable(page))
! {
! /* Okay to use page. Re-initialize and return it */
! _bt_pageinit(page, BufferGetPageSize(buf));
! return buf;
! }
! elog(DEBUG2, "FSM returned nonrecyclable page");
! _bt_relbuf(rel, buf);
! }
! else
! {
! elog(DEBUG2, "FSM returned nonlockable page");
! /* couldn't get lock, so just drop pin */
! ReleaseBuffer(buf); } } /*
*** src/backend/storage/buffer/bufmgr.c.orig Sun Aug 3 23:00:55 2003
--- src/backend/storage/buffer/bufmgr.c Sun Aug 10 15:17:28 2003
***************
*** 1937,1942 ****
--- 1937,1973 ---- } /*
+ * Acquire the cntx_lock for the buffer, but only if we don't have to wait.
+ *
+ * This assumes the caller wants BUFFER_LOCK_EXCLUSIVE mode.
+ */
+ bool
+ ConditionalLockBuffer(Buffer buffer)
+ {
+ BufferDesc *buf;
+
+ Assert(BufferIsValid(buffer));
+ if (BufferIsLocal(buffer))
+ return true; /* act as though we got it */
+
+ buf = &(BufferDescriptors[buffer - 1]);
+
+ if (LWLockConditionalAcquire(buf->cntx_lock, LW_EXCLUSIVE))
+ {
+ /*
+ * This is not the best place to set cntxDirty flag (eg indices do
+ * not always change buffer they lock in excl mode). But please
+ * remember that it's critical to set cntxDirty *before* logging
+ * changes with XLogInsert() - see comments in BufferSync().
+ */
+ buf->cntxDirty = true;
+
+ return true;
+ }
+ return false;
+ }
+
+ /* * LockBufferForCleanup - lock a buffer in preparation for deleting items * * Items may be deleted from a disk
pageonly when the caller (a) holds an
*** src/include/storage/bufmgr.h.orig Sun Aug 3 23:01:42 2003
--- src/include/storage/bufmgr.h Sun Aug 10 15:12:06 2003
***************
*** 180,185 ****
--- 180,186 ---- extern void UnlockBuffers(void); extern void LockBuffer(Buffer buffer, int mode);
+ extern bool ConditionalLockBuffer(Buffer buffer); extern void LockBufferForCleanup(Buffer buffer); extern void
AbortBufferIO(void);