'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
buffercontent 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:
RowExclusiveLockon 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
ontable 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:
AccessShareLockon table set_type (2112116436)   granted: AccessShareLock on table data_store (2112116520)   granted:
AccessShareLockon 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:
RowExclusiveLockon 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
tablefeature_link (2112116486)   granted: AccessShareLock on table sequence_type (2112116441)   granted:
AccessShareLockon 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:
AccessShareLockon 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
tablesequence_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    | t2112116466 | 2112078897
|            | 17983 | AccessShareLock  | t2112085544 | 2112078897 |             | 17983 | RowExclusiveLock | t
 |            |    26991864 | 17983 | ExclusiveLock    | t2112116520 | 2112078897 |             | 17980 |
AccessShareLock | t2112116407 | 2112078897 |             | 18084 | AccessShareLock  | t2112116456 | 2112078897 |
    | 17983 | AccessShareLock  | t2112085549 | 2112078897 |             | 17980 | RowExclusiveLock | t2112117357 |
2112078897|             | 17983 | RowExclusiveLock | t2112116461 | 2112078897 |             | 17983 | AccessShareLock
|t           |            |    26990698 | 17981 | ExclusiveLock    | t2112116530 | 2112078897 |             | 17980 |
AccessShareLock | t2112085544 | 2112078897 |             | 17980 | RowExclusiveLock | t           |            |
26991878| 17980 | ExclusiveLock    | t2112116486 | 2112078897 |             | 17983 | RowExclusiveLock | t2112117699 |
2112078897|             | 18084 | AccessShareLock  | t2112116530 | 2112078897 |             | 17983 | AccessShareLock
|t2112116535 | 2112078897 |             | 17983 | AccessShareLock  | t2112116471 | 2112078897 |             | 17980 |
AccessShareLock | t2124233471 | 2112078897 |             | 17980 | ExclusiveLock    | t2112116436 | 2112078897 |
    | 18084 | AccessShareLock  | t2112116535 | 2112078897 |             | 17980 | AccessShareLock  | t2112116476 |
2112078897|             | 17980 | AccessShareLock  | t           |            |    26990811 | 17977 | ExclusiveLock
|t2112116451 | 2112078897 |             | 17980 | AccessShareLock  | t     16837 | 2112078897 |             | 23060 |
AccessShareLock | t2112116451 | 2112078897 |             | 17983 | AccessShareLock  | t2112116441 | 2112078897 |
    | 17983 | AccessShareLock  | t2112116515 | 2112078897 |             | 17983 | AccessShareLock  | t2112116525 |
2112078897|             | 17983 | AccessShareLock  | t2112116515 | 2112078897 |             | 17980 | AccessShareLock
|t2112116471 | 2112078897 |             | 17983 | AccessShareLock  | t           |            |    27016842 | 18084 |
ExclusiveLock   | t2112116476 | 2112078897 |             | 17983 | AccessShareLock  | t2112116486 | 2112078897 |
    | 17980 | RowExclusiveLock | t2112116441 | 2112078897 |             | 17980 | AccessShareLock  | t2112116525 |
2112078897|             | 17980 | AccessShareLock  | t           |            |    27018036 | 17976 | ExclusiveLock
|t2112116431 | 2112078897 |             | 17980 | AccessShareLock  | t2112116456 | 2112078897 |             | 17980 |
AccessShareLock | t2112085549 | 2112078897 |             | 17983 | RowExclusiveLock | t2112116436 | 2112078897 |
    | 17980 | AccessShareLock  | t2112116436 | 2112078897 |             | 17983 | AccessShareLock  | t2112117337 |
2112078897|             | 17980 | RowExclusiveLock | t2112116461 | 2112078897 |             | 17980 | AccessShareLock
|t2112117357 | 2112078897 |             | 17980 | RowExclusiveLock | t2112116466 | 2112078897 |             | 17980 |
AccessShareLock | t2112116520 | 2112078897 |             | 17983 | AccessShareLock  | t           |            |
26991357| 17982 | ExclusiveLock    | t           |            |    27018054 | 23060 | ExclusiveLock    | t2124233471 |
2112078897|             | 17983 | ExclusiveLock    | f2112116431 | 2112078897 |             | 17983 | AccessShareLock
|t2112116431 | 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)