Hi,

In the meantime we were able to upgrade to PostgreSQL 7.3.4+Tom's patch
to datetime.c [see 'Postgresql 7.3.3 crashing on query' thread].

Now if the applications issues one delete statement concurrently on
two connections both block forever.

Please correct me if I am wrong, but should not one of the statements
succeed and the other simply fail ?

Aug 18 10:34:25 nut1 postgres[4934]: [44389] LOG:
query: delete from Calls where objID = 2268645

Aug 18 10:34:25 nut1 postgres[4933]: [44071] LOG:
query: delete from Calls where objID = 2268645


Architecture: i386, OS: Debian

And here the full info:

sd=> SELECT l.mode, l.granted, l.pid, l.transaction, d.datname, r.relname FROM pg_locks l, pg_database d, pg_class r WHERE d.oid=l.database AND r.oid=l.relation;
mode | granted | pid | transaction | datname | relname
------------------+---------+-------+-------------+---------+------------------------------
AccessShareLock | t | 26836 | | sd | pg_locks
AccessShareLock | t | 26836 | | sd | pg_class
AccessShareLock | t | 22486 | | sd | callactivities
AccessShareLock | t | 4935 | | sd | callactivities
AccessShareLock | t | 22487 | | sd | callactivities
AccessShareLock | t | 22486 | | sd | bppersons
AccessShareLock | t | 22487 | | sd | bppersons
AccessShareLock | t | 4935 | | sd | bppersons
AccessShareLock | t | 4935 | | sd | priorities
AccessShareLock | t | 22487 | | sd | priorities
AccessShareLock | t | 22486 | | sd | priorities
AccessShareLock | t | 22487 | | sd | callstates
AccessShareLock | t | 4935 | | sd | callstates
AccessShareLock | t | 22486 | | sd | callstates
AccessShareLock | t | 4935 | | sd | queues
AccessShareLock | t | 22487 | | sd | queues
AccessShareLock | t | 22486 | | sd | queues
AccessShareLock | t | 22486 | | sd | timezones
AccessShareLock | t | 4935 | | sd | timezones
AccessShareLock | t | 22487 | | sd | timezones
AccessShareLock | t | 22486 | | sd | calls
RowExclusiveLock | t | 4934 | | sd | calls
AccessShareLock | t | 4934 | | sd | calls
AccessShareLock | t | 4935 | | sd | calls
RowExclusiveLock | t | 4933 | | sd | calls
AccessShareLock | t | 4933 | | sd | calls
AccessShareLock | t | 22487 | | sd | calls
AccessShareLock | t | 22487 | | sd | bporganizations
AccessShareLock | t | 22486 | | sd | bporganizations
AccessShareLock | t | 4935 | | sd | bporganizations
AccessShareLock | t | 22487 | | sd | problemtypes
AccessShareLock | t | 22486 | | sd | problemtypes
AccessShareLock | t | 4935 | | sd | problemtypes
AccessShareLock | t | 4935 | | sd | contractelements
AccessShareLock | t | 22486 | | sd | contractelements
AccessShareLock | t | 22487 | | sd | contractelements
AccessShareLock | t | 4935 | | sd | contracts
AccessShareLock | t | 22487 | | sd | contracts
AccessShareLock | t | 22486 | | sd | contracts
AccessShareLock | t | 22487 | | sd | bpartners
AccessShareLock | t | 4935 | | sd | bpartners
AccessShareLock | t | 22486 | | sd | bpartners
AccessShareLock | t | 22487 | | sd | callcalculations
AccessShareLock | t | 22486 | | sd | callcalculations
AccessShareLock | t | 4935 | | sd | callcalculations
AccessShareLock | t | 22487 | | sd | chargingtypes
AccessShareLock | t | 22486 | | sd | chargingtypes
AccessShareLock | t | 4935 | | sd | chargingtypes
AccessShareLock | t | 22487 | | sd | dictpropertysethasproperties
AccessShareLock | t | 4935 | | sd | dictpropertysethasproperties
AccessShareLock | t | 22486 | | sd | dictpropertysethasproperties
AccessShareLock | t | 22487 | | sd | concretepropertysets
AccessShareLock | t | 4935 | | sd | concretepropertysets
AccessShareLock | t | 22486 | | sd | concretepropertysets
AccessShareLock | t | 22486 | | sd | concretepropertyvalues
AccessShareLock | t | 4935 | | sd | concretepropertyvalues
AccessShareLock | t | 22487 | | sd | concretepropertyvalues
AccessShareLock | t | 4935 | | sd | dictproperties
AccessShareLock | t | 22486 | | sd | dictproperties
AccessShareLock | t | 22487 | | sd | dictproperties
AccessShareLock | t | 4934 | | sd | calls_pkey
(61 rows)

3936 ? S 0:00 postgres: stats buffer process
3937 ? S 0:00 postgres: stats collector process
4555 ? S 69:38 postgres: sd sd 10.2.2.6 idle
4556 ? S 0:07 postgres: sd sd 10.2.2.6 idle
4621 ? S 11:19 postgres: sd sd 10.2.2.6 idle
4632 ? S 10:08 postgres: sd sd 10.2.2.6 idle
4764 ? S 0:04 postgres: sd sd 10.2.1.5 idle
4933 ? S 5:20 postgres: sd sd 10.2.1.5 idle in transaction
4934 ? S 5:08 postgres: sd sd 10.2.1.5 DELETE waiting
4935 ? S 6:00 postgres: sd sd 10.2.1.5 idle in transaction
4936 ? S 4:54 postgres: sd sd 10.2.1.5 idle
4937 ? S 5:30 postgres: sd sd 10.2.1.5 idle
4938 ? S 6:17 postgres: sd sd 10.2.1.5 idle
4939 ? S 6:23 postgres: sd sd 10.2.1.5 idle
22486 ? S 1:40 postgres: sd sd 10.2.1.5 idle in transaction
22487 ? S 1:54 postgres: sd sd 10.2.1.5 idle in transaction
24211 pts/2 S 0:00 /usr/lib/postgresql/bin/psql -d sd
24218 ? S 0:00 postgres: sd sd [local] idle
26753 ? S 0:00 postgres: sd sd 10.2.1.5 idle

Aug 18 10:34:25 nut1 postgres[4934]: [44383-1] LOG: query: select objID, ID, CustCallID, SPCallID, cel_objid, con_objid, ccu_objid, csp_objid, csf_objid, fro_objid,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-2] to1_objid, to2_objid, CallerSLA, CallOpenTime, CallOpenTimeUTC, CallResponseTime, CallResponseTimeUTC, CallCloseTime,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-3] CallCloseTimeUTC, CallReceiveTime, CallReceiveTimeUTC, CallSendTime, CallSendTimeUTC, ProblemStartTime, ProblemStartTimeUTC,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-4] EndOfResponseTime, EndOfResponseTimeUTC, RemainingResponseMinutes, EndOfRecoveryTime, EndOfRecoveryTimeUTC,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-5] RemainingRecoveryMinutes, CallStateChangeTime, CallStateChangeTimeUTC, CallAcknowledgeTime, CallAcknowledgeTimeUTC,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-6] CallerShortName, CallerFirstName, CallerLastName, CallerTitle, CallerSalutation, CallerTel, CallerTel2, CallerMobileTel,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-7] CallerFax, CallerLocationZip, CallerLocationCity, CallerLocationStreet, CallerLocationCountry, CallerLocation, CallerEMail,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-8] CallerPIN, CallerDescription, CallerDepartment, CallerSign, MainCompManfacturer, MainCompType, MainCompModel, MainComponent,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-9] MainCompName, MainCompSerNr, MainCompInvNr, MainCompSerNrProv, MainCompOpSys, MainCompLocationZip, MainCompLocationCity,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-10] MainCompLocationStreet, MainCompLocationCountry, MainCompLocation, MainCompLocationTel, MainCompDescription,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-11] MainCompLocationName, pro_objid, pcu_objid, psp_objid, psf_objid, pgl_objid, sev_objid, fat_objid, cst_objid, pst_objid,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-12] cac_objid, ema_objid, InternalState, CallProvedFlag, ShortDescription, Description, Remarks, Diagnosis, edi_objid, EditTime,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-13] EditTimeUTC, csc_objid, css_objid, csu_objid, cal_objid, SubCompManfacturer, SubCompType, SubCompModel, SubComponent,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-14] SubCompName, SubCompSerNr, SubCompInvNr, SubCompSerNrProv, SubCompOpSys, SubCompLocationZip, SubCompLocationCity,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-15] SubCompLocationStreet, SubCompLocationCountry, SubCompLocation, SubCompLocationTel, SubCompDescription, SubCompLocationName,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-16] SysSpecField1, SysSpecField2, SysSpecField3, SysSpecField4, SysSpecField5, SysSpecField6, SysSpecField7, SysSpecField8,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-17] SysSpecField9, SysSpecField10, XML_Info, CHDShortName, CHDFirstName, CHDLastName, CHDTitle, CHDSalutation, CHDTel, CHDTel2,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-18] CHDMobileTel, CHDFax, CHDLocationZip, CHDLocationCity, CHDLocationStreet, CHDLocationCountry, CHDLocation, CHDEMail, CHDPIN,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-19] CHDDescription, CHDDepartment, CHDSign, CCPShortName, CCPFirstName, CCPLastName, CCPTitle, CCPSalutation, CCPTel, CCPTel2,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-20] CCPMobileTel, CCPFax, CCPLocationZip, CCPLocationCity, CCPLocationStreet, CCPLocationCountry, CCPLocation, CCPEMail, CCPPIN,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-21] CCPDescription, CCPDepartment, CCPSign, bpr_objid, SlaResponseMinutes, SlaRecoveryMinutes, TotalResponseMinutes,
Aug 18 10:34:25 nut1 postgres[4934]: [44383-22] TotalRecoveryMinutes, TotalAcknowledgeMinutes, Zone, unspsc, dev_objid, tzo_objid, isTestCall, que_objid, tec_objid from Calls
Aug 18 10:34:25 nut1 postgres[4934]: [44383-23] where ID = 2266388
Aug 18 10:34:25 nut1 postgres[4934]: [44384] LOG: duration: 0.007914 sec
Aug 18 10:34:25 nut1 postgres[4934]: [44385] LOG: query: select objID, ID, ShortName, Name, TZID, UTCRawOffset from TimeZones where objID = 1000040000
Aug 18 10:34:25 nut1 postgres[4934]: [44386] LOG: duration: 0.001898 sec
Aug 18 10:34:25 nut1 postgres[4934]: [44387] LOG: query: begin;
Aug 18 10:34:25 nut1 postgres[4934]: [44388] LOG: duration: 0.000117 sec
Aug 18 10:34:25 nut1 postgres[4934]: [44389] LOG: query: delete from Calls where objID = 2268645
Aug 18 10:39:18 nut1 postgres[4934]: [44390] LOG: duration: 292.649273 sec
Aug 18 10:39:18 nut1 postgres[4934]: [44391] LOG: pq_recvbuf: unexpected EOF on client connection


Aug 18 10:34:25 nut1 postgres[4933]: [44067-1] LOG: query: select objID, ID, CustCallID, SPCallID, cel_objid, con_objid, ccu_objid, csp_objid, csf_objid, fro_objid,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-2] to1_objid, to2_objid, CallerSLA, CallOpenTime, CallOpenTimeUTC, CallResponseTime, CallResponseTimeUTC, CallCloseTime,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-3] CallCloseTimeUTC, CallReceiveTime, CallReceiveTimeUTC, CallSendTime, CallSendTimeUTC, ProblemStartTime, ProblemStartTimeUTC,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-4] EndOfResponseTime, EndOfResponseTimeUTC, RemainingResponseMinutes, EndOfRecoveryTime, EndOfRecoveryTimeUTC,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-5] RemainingRecoveryMinutes, CallStateChangeTime, CallStateChangeTimeUTC, CallAcknowledgeTime, CallAcknowledgeTimeUTC,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-6] CallerShortName, CallerFirstName, CallerLastName, CallerTitle, CallerSalutation, CallerTel, CallerTel2, CallerMobileTel,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-7] CallerFax, CallerLocationZip, CallerLocationCity, CallerLocationStreet, CallerLocationCountry, CallerLocation, CallerEMail,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-8] CallerPIN, CallerDescription, CallerDepartment, CallerSign, MainCompManfacturer, MainCompType, MainCompModel, MainComponent,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-9] MainCompName, MainCompSerNr, MainCompInvNr, MainCompSerNrProv, MainCompOpSys, MainCompLocationZip, MainCompLocationCity,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-10] MainCompLocationStreet, MainCompLocationCountry, MainCompLocation, MainCompLocationTel, MainCompDescription,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-11] MainCompLocationName, pro_objid, pcu_objid, psp_objid, psf_objid, pgl_objid, sev_objid, fat_objid, cst_objid, pst_objid,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-12] cac_objid, ema_objid, InternalState, CallProvedFlag, ShortDescription, Description, Remarks, Diagnosis, edi_objid, EditTime,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-13] EditTimeUTC, csc_objid, css_objid, csu_objid, cal_objid, SubCompManfacturer, SubCompType, SubCompModel, SubComponent,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-14] SubCompName, SubCompSerNr, SubCompInvNr, SubCompSerNrProv, SubCompOpSys, SubCompLocationZip, SubCompLocationCity,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-15] SubCompLocationStreet, SubCompLocationCountry, SubCompLocation, SubCompLocationTel, SubCompDescription, SubCompLocationName,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-16] SysSpecField1, SysSpecField2, SysSpecField3, SysSpecField4, SysSpecField5, SysSpecField6, SysSpecField7, SysSpecField8,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-17] SysSpecField9, SysSpecField10, XML_Info, CHDShortName, CHDFirstName, CHDLastName, CHDTitle, CHDSalutation, CHDTel, CHDTel2,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-18] CHDMobileTel, CHDFax, CHDLocationZip, CHDLocationCity, CHDLocationStreet, CHDLocationCountry, CHDLocation, CHDEMail, CHDPIN,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-19] CHDDescription, CHDDepartment, CHDSign, CCPShortName, CCPFirstName, CCPLastName, CCPTitle, CCPSalutation, CCPTel, CCPTel2,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-20] CCPMobileTel, CCPFax, CCPLocationZip, CCPLocationCity, CCPLocationStreet, CCPLocationCountry, CCPLocation, CCPEMail, CCPPIN,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-21] CCPDescription, CCPDepartment, CCPSign, bpr_objid, SlaResponseMinutes, SlaRecoveryMinutes, TotalResponseMinutes,
Aug 18 10:34:25 nut1 postgres[4933]: [44067-22] TotalRecoveryMinutes, TotalAcknowledgeMinutes, Zone, unspsc, dev_objid, tzo_objid, isTestCall, que_objid, tec_objid from Calls
Aug 18 10:34:25 nut1 postgres[4933]: [44067-23] where ID = 2265302
Aug 18 10:34:25 nut1 postgres[4933]: [44068] LOG: duration: 0.008038 sec
Aug 18 10:34:25 nut1 postgres[4933]: [44069] LOG: query: begin;
Aug 18 10:34:25 nut1 postgres[4933]: [44070] LOG: duration: 0.000121 sec
Aug 18 10:34:25 nut1 postgres[4933]: [44071] LOG: query: delete from Calls where objID = 2268645
Aug 18 10:34:25 nut1 postgres[4933]: [44072] LOG: duration: 0.000675 sec
Aug 18 10:39:18 nut1 postgres[4933]: [44073] LOG: pq_recvbuf: unexpected EOF on client connection

-Philipp
--
: Dipl-Ing Philipp Reisner Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH Fax +43-1-8178292-82 :
: Schönbrunnerstr 244, 1120 Vienna, Austria http://www.linbit.com :


---------------------------(end of broadcast)---------------------------
TIP 9: the planner will ignore your desire to choose an index scan if your
joining column's datatypes do not match

Philipp Reisner <philipp.reisner (AT) linbit (DOT) com> writes:
I see no deadlock. 4933 is waiting for its client to issue another
command. 4934 is waiting to see if it can delete the row.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 3: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo (AT) postgresql (DOT) org so that your
message can get through to the mailing list cleanly

Am Montag, 18. August 2003 15:38 schrieb Tom Lane:
Hi Tom,

Right, thanks for pointing it out for me. It seems to be somwhere in
the application code or PostgreSQL's jdbc driver.

Finally we are able to reproduce the "Lockup" and we will continue
to work out if it is in the App or in the jdbc driver.

-Philipp
--
: Dipl-Ing Philipp Reisner Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH Fax +43-1-8178292-82 :
: Schönbrunnerstr 244, 1120 Vienna, Austria http://www.linbit.com :


---------------------------(end of broadcast)---------------------------
TIP 8: explain analyze is your friend

Am Dienstag, 19. August 2003 11:52 schrieb Philipp Reisner:
Just in order to end this thread. It turned out that the lockup was
triggered by an old version of postgres' jdbc driver. (It was from
the 7.2.1 days of postgresql)

Updating to a recent version finaly solved this issue.

-Philipp


---------------------------(end of broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmaster