'COPY ... FROM' inserts to btree, blocks on buffer writeout

Hi,

two concurrent clients try to 'COPY ... FROM ...' to the same table,
"feature_link".

The second one (pid 17983) is waiting for an ExclusiveLock on the table's
primary key index, "key__idpk__flink".

The first one (pid 17980) is inserting into the index's btree, waiting
for a buffer lock. This locking state seems to persist.

Do you have any idea what could cause this scenario and what kind of
debugging information I could extract (the processes are still running) to
find out who is currently holding the buffer lock in question?

Thanks for your help,
best wishes, Mike

[fuchs:~/build/postgresql-8.0.0beta2] vi +1004 ./src/backend/storage/buffer/bufmgr.c
999 /*
1000 * Protect buffer content against concurrent update. (Note that
1001 * hint-bit updates can still occur while the write is in progress,
1002 * but we assume that that will not invalidate the data written.)
1003 */
1004 LockBuffer(buffer, BUFFER_LOCK_SHARE);
1005

[fuchs:~/build/postgresql-8.0.0beta2] gdb src/backend/postgres
[...]
(gdb) attach 17980
[...]
(gdb) where
#0 0x0000002a96181279 in semop () from /lib64/tls/libc.so.6
#1 0x0000000000511707 in PGSemaphoreLock (sema=0x2aa16de2f0, interruptOK=0 '\0') at pg_sema.c:418
#2 0x000000000053549a in LWLockAcquire (lockid=32741, mode=LW_SHARED) at lwlock.c:315
#3 0x0000000000528a3d in FlushBuffer (buf=0x2a9953ea40, reln=0x900640) at bufmgr.c:1004
#4 0x000000000052806d in BufferAlloc (reln=0x2768021, blockNum=3220402560, foundPtr=0x7fbff3728f "") at bufmgr.c:365
#5 0x0000000000527edc in ReadBufferInternal (reln=0x2aa24786b8, blockNum=20055, bufferLockHeld=0 '\0') at bufmgr.c:153
#6 0x000000000044a930 in _bt_getbuf (rel=0x2aa24786b8, blkno=3220402560, access=2) at nbtpage.c:492
#7 0x0000000000448c87 in _bt_split (rel=0x2aa24786b8, buf=673, firstright=89, newitemoff=164, newitemsz=40, newitem=0x911d40, newitemonleft=0 '\0',
itup_off=0x7fbff374c6, itup_blkno=0x7fbff374c8) at nbtinsert.c:683
#8 0x00000000004486ba in _bt_insertonpg (rel=0x2aa24786b8, buf=673, stack=0x9924f0, keysz=1, scankey=0x911d90, btitem=0x911d40, afteritem=0,
split_only_page=0 '\0') at nbtinsert.c:500
#9 0x00000000004481eb in _bt_doinsert (rel=0x2aa24786b8, btitem=0x911d40, index_is_unique=1 '\001', heapRel=0x2aa2477c38) at nbtinsert.c:141
#10 0x000000000044bb71 in btinsert (fcinfo=0x2768021) at nbtree.c:257
#11 0x00000000005a44aa in OidFunctionCall6 (functionId=41320481, arg1=183111222968, arg2=548681250960, arg3=548681250928, arg4=9515332,
arg5=183111220280, arg6=18446744073709551612) at fmgr.c:1487
#12 0x00000000004476a5 in index_insert (indexRelation=0x2aa24786b8, datums=0x7fbff37890, nulls=0x7fbff37870 " î", heap_t_ctid=0x913144,
heapRelation=0x2aa2477c38, check_uniqueness=1 '\001') at indexam.c:226
#13 0x00000000004cf3cf in ExecInsertIndexTuples (slot=0x0, tupleid=0x7fbff37180, estate=0x990450, is_vacuum=0 '\0') at execUtils.c:859
#14 0x000000000049c1d1 in CopyFrom (rel=0x2aa2477c38, attnumlist=0x990060, binary=0 '\0', oids=0 '\0', delim=0x63e4cd "\t", null_print=0x608614 "\\N",
csv_mode=0 '\0', quote=0x0, escape=0x0, force_notnull_atts=0x911cb0) at copy.c:1958
#15 0x000000000049a34f in DoCopy (stmt=0x2768021) at copy.c:1043
#16 0x000000000053d7b9 in PortalRunUtility (portal=0x906b40, query=0x8fa5f0, dest=0x8fa910, completionTag=0x7fbff37f60 "") at pquery.c:839
#17 0x000000000053da41 in PortalRunMulti (portal=0x906b40, dest=0x8fa910, altdest=0x8fa910, completionTag=0x7fbff37f60 "") at pquery.c:902
---Type <return> to continue, or q <return> to quit---
#18 0x000000000053d230 in PortalRun (portal=0x906b40, count=9223372036854775807, dest=0x8fa910, altdest=0x8fa910, completionTag=0x7fbff37f60 "")
at pquery.c:543
#19 0x0000000000539c59 in exec_simple_query (
query_string=0x8fa700 "COPY feature_link from '/anniedev1/impseb/datastore/results/2004/12/29/22/38/bio:query:ncbi-blast:10562062.out_featurelink'")
at postgres.c:924
#20 0x000000000053bf6d in PostgresMain (argc=9414400, argv=0x86f028, username=0x86eff0 "annieseb") at postgres.c:2970
#21 0x0000000000514db7 in BackendRun (port=0x89c650) at postmaster.c:2848
#22 0x0000000000514850 in BackendStartup (port=0x89c650) at postmaster.c:2470
#23 0x0000000000512fde in ServerLoop () at postmaster.c:1215
#24 0x0000000000512446 in PostmasterMain (argc=1, argv=0x804850) at postmaster.c:898
#25 0x00000000004e3206 in main (argc=1, argv=0x804850) at main.c:265

[fuchs:/anniedev1/impseb/work/annie] ps -ef | grep impseb2 | grep -v grep | sort
anniedb2 17976 21254 0 Dec29 ? 00:03:50 postgres: annieseb impseb2 10.44.1.20(33855) idle in transaction
anniedb2 17977 21254 0 Dec29 ? 00:01:38 postgres: annieseb impseb2 10.44.1.20(33856) idle in transaction
anniedb2 17979 21254 0 Dec29 ? 00:03:21 postgres: annieseb impseb2 10.44.1.20(33857) idle in transaction
anniedb2 17980 21254 0 Dec29 ? 00:02:26 postgres: annieseb impseb2 10.44.1.20(33858) COPY
anniedb2 17981 21254 0 Dec29 ? 00:00:53 postgres: annieseb impseb2 10.44.1.20(33859) idle in transaction
anniedb2 17982 21254 0 Dec29 ? 00:03:31 postgres: annieseb impseb2 10.44.1.20(33860) idle in transaction
anniedb2 17983 21254 0 Dec29 ? 00:03:34 postgres: annieseb impseb2 10.44.1.20(33861) COPY waiting
anniedb2 18084 21254 0 Dec29 ? 00:03:15 postgres: annieseb impseb2 10.44.1.20(33863) idle in transaction
anniedb2 23066 21254 0 17:45 ? 00:00:00 postgres: annieseb impseb2 10.44.1.21(45361) idle

[fuchs:/anniedev1/impseb/work/annie] bin/pg-dump-locks
pid 17979
pid 23130
granted: AccessShareLock on table pg_locks (16837)
granted: AccessShareLock on table pg_class (1259)
granted: AccessShareLock on table pg_index (16390)
pid 17981
pid 17983
waiting: ExclusiveLock on table key__idpk__flink (2124233471)
granted: RowExclusiveLock on table ncbi_blast_result (2112117337)
granted: AccessShareLock on table nmt_parameter_set (2112116466)
granted: RowExclusiveLock on table ncbi_blast_round (2112085544)
granted: AccessShareLock on table gpi_learning_set (2112116456)
granted: RowExclusiveLock on table ncbi_blast_alignment (2112117357)
granted: AccessShareLock on table gpi3_learning_set (2112116461)
granted: RowExclusiveLock on table feature_link (2112116486)
granted: AccessShareLock on table managed_file_group (2112116530)
granted: AccessShareLock on table algorithm_index_file (2112116535)
granted: AccessShareLock on table def_parser_type (2112116451)
granted: AccessShareLock on table sequence_type (2112116441)
granted: AccessShareLock on table file_type (2112116515)
granted: AccessShareLock on table managed_file (2112116525)
granted: AccessShareLock on table ptsone_function (2112116471)
granted: AccessShareLock on table toppred_function (2112116476)
granted: RowExclusiveLock on table ncbi_blast_subject (2112085549)
granted: AccessShareLock on table set_type (2112116436)
granted: AccessShareLock on table data_store (2112116520)
granted: AccessShareLock on table sequence_alphabet (2112116431)
pid 17980
granted: AccessShareLock on table data_store (2112116520)
granted: RowExclusiveLock on table ncbi_blast_subject (2112085549)
granted: AccessShareLock on table managed_file_group (2112116530)
granted: RowExclusiveLock on table ncbi_blast_round (2112085544)
granted: AccessShareLock on table ptsone_function (2112116471)
granted: ExclusiveLock on table key__idpk__flink (2124233471)
granted: AccessShareLock on table algorithm_index_file (2112116535)
granted: AccessShareLock on table toppred_function (2112116476)
granted: AccessShareLock on table def_parser_type (2112116451)
granted: AccessShareLock on table file_type (2112116515)
granted: RowExclusiveLock on table feature_link (2112116486)
granted: AccessShareLock on table sequence_type (2112116441)
granted: AccessShareLock on table managed_file (2112116525)
granted: AccessShareLock on table sequence_alphabet (2112116431)
granted: AccessShareLock on table gpi_learning_set (2112116456)
granted: AccessShareLock on table set_type (2112116436)
granted: RowExclusiveLock on table ncbi_blast_result (2112117337)
granted: AccessShareLock on table gpi3_learning_set (2112116461)
granted: RowExclusiveLock on table ncbi_blast_alignment (2112117357)
granted: AccessShareLock on table nmt_parameter_set (2112116466)
pid 17982
pid 18084
granted: AccessShareLock on table changeable_bio_set (2112116407)
granted: AccessShareLock on table ojb_splice_list (2112117699)
granted: AccessShareLock on table set_type (2112116436)
granted: AccessShareLock on table sequence_alphabet (2112116431)
pid 17976
pid 17977

impseb2=# select * from pg_locks;
relation | database | transaction | pid | mode | granted
------------+------------+-------------+-------+------------------+---------
2112117337 | 2112078897 | | 17983 | RowExclusiveLock | t
| | 26991056 | 17979 | ExclusiveLock | t
2112116466 | 2112078897 | | 17983 | AccessShareLock | t
2112085544 | 2112078897 | | 17983 | RowExclusiveLock | t
| | 26991864 | 17983 | ExclusiveLock | t
2112116520 | 2112078897 | | 17980 | AccessShareLock | t
2112116407 | 2112078897 | | 18084 | AccessShareLock | t
2112116456 | 2112078897 | | 17983 | AccessShareLock | t
2112085549 | 2112078897 | | 17980 | RowExclusiveLock | t
2112117357 | 2112078897 | | 17983 | RowExclusiveLock | t
2112116461 | 2112078897 | | 17983 | AccessShareLock | t
| | 26990698 | 17981 | ExclusiveLock | t
2112116530 | 2112078897 | | 17980 | AccessShareLock | t
2112085544 | 2112078897 | | 17980 | RowExclusiveLock | t
| | 26991878 | 17980 | ExclusiveLock | t
2112116486 | 2112078897 | | 17983 | RowExclusiveLock | t
2112117699 | 2112078897 | | 18084 | AccessShareLock | t
2112116530 | 2112078897 | | 17983 | AccessShareLock | t
2112116535 | 2112078897 | | 17983 | AccessShareLock | t
2112116471 | 2112078897 | | 17980 | AccessShareLock | t
2124233471 | 2112078897 | | 17980 | ExclusiveLock | t
2112116436 | 2112078897 | | 18084 | AccessShareLock | t
2112116535 | 2112078897 | | 17980 | AccessShareLock | t
2112116476 | 2112078897 | | 17980 | AccessShareLock | t
| | 26990811 | 17977 | ExclusiveLock | t
2112116451 | 2112078897 | | 17980 | AccessShareLock | t
16837 | 2112078897 | | 23060 | AccessShareLock | t
2112116451 | 2112078897 | | 17983 | AccessShareLock | t
2112116441 | 2112078897 | | 17983 | AccessShareLock | t
2112116515 | 2112078897 | | 17983 | AccessShareLock | t
2112116525 | 2112078897 | | 17983 | AccessShareLock | t
2112116515 | 2112078897 | | 17980 | AccessShareLock | t
2112116471 | 2112078897 | | 17983 | AccessShareLock | t
| | 27016842 | 18084 | ExclusiveLock | t
2112116476 | 2112078897 | | 17983 | AccessShareLock | t
2112116486 | 2112078897 | | 17980 | RowExclusiveLock | t
2112116441 | 2112078897 | | 17980 | AccessShareLock | t
2112116525 | 2112078897 | | 17980 | AccessShareLock | t
| | 27018036 | 17976 | ExclusiveLock | t
2112116431 | 2112078897 | | 17980 | AccessShareLock | t
2112116456 | 2112078897 | | 17980 | AccessShareLock | t
2112085549 | 2112078897 | | 17983 | RowExclusiveLock | t
2112116436 | 2112078897 | | 17980 | AccessShareLock | t
2112116436 | 2112078897 | | 17983 | AccessShareLock | t
2112117337 | 2112078897 | | 17980 | RowExclusiveLock | t
2112116461 | 2112078897 | | 17980 | AccessShareLock | t
2112117357 | 2112078897 | | 17980 | RowExclusiveLock | t
2112116466 | 2112078897 | | 17980 | AccessShareLock | t
2112116520 | 2112078897 | | 17983 | AccessShareLock | t
| | 26991357 | 17982 | ExclusiveLock | t
| | 27018054 | 23060 | ExclusiveLock | t
2124233471 | 2112078897 | | 17983 | ExclusiveLock | f
2112116431 | 2112078897 | | 17983 | AccessShareLock | t
2112116431 | 2112078897 | | 18084 | AccessShareLock | t
(54 rows)

--
Do not feel safe. The poet remembers. DI Michael Wildpaner
You can kill one, but another is born. Ph.D. Student
The words are written down,
the deed, the date. (Czeslaw Milosz)