Re: Deadlock in PostgreSQL 7.3.4

Hi,

We use postgresql 7.2.1 (actually the Debian binary packet version
7.2.1-2woody2)
Our database load has more QUERIES than INSERT/DELETES. But we have a
sever problem with the wirting operations.

Once in a while (about 3 times a day) one or more INSERTS/DELETES simply
go into the "waiting" state, and block the whole database. The only way
out is to terminate the client connection (i.e. to abort the blocked
INSERT/DELETE query)

Further investigation with ps -e -o wchan... showed that the backed
process was simply sleeping in "semop".

Output of ps:

762 ? S 0:00 /usr/lib/postgresql/bin/postmaster
764 ? S 0:00 postgres: stats buffer process
765 ? S 0:00 postgres: stats collector process
24872 ? S 0:00 postgres: sd sd 10.2.2.6 idle in transaction
24873 ? R 68:01 postgres: sd sd 10.2.2.6 SELECT
24932 ? S 3:09 postgres: sd sd 10.2.2.6 idle in transaction
24943 ? R 3:02 postgres: sd sd 10.2.2.6 SELECT
25004 ? S 0:01 postgres: sd sd 10.2.1.5 idle in transaction
21226 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
21228 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
21229 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
21230 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
21231 ? S 0:01 postgres: sd sd 10.2.1.5 idle in transaction
21232 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
21227 ? S 0:01 postgres: sd sd 10.2.1.5 INSERT waiting
21391 pts/1 S 0:00 grep postg

762 ? S 0:00 /usr/lib/postgresql/bin/postmaster
764 ? S 0:00 postgres: stats buffer process
765 ? S 0:00 postgres: stats collector process
24872 ? S 0:00 postgres: sd sd 10.2.2.6 idle in transaction
24873 ? S 68:02 postgres: sd sd 10.2.2.6 idle in transaction
24932 ? S 3:09 postgres: sd sd 10.2.2.6 idle in transaction
24943 ? S 3:04 postgres: sd sd 10.2.2.6 idle in transaction
25004 ? S 0:01 postgres: sd sd 10.2.1.5 idle in transaction
21226 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
21228 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
21229 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
21230 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
21231 ? S 0:01 postgres: sd sd 10.2.1.5 idle in transaction
21232 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
21227 ? S 0:01 postgres: sd sd 10.2.1.5 INSERT waiting

762 ? S 0:00 /usr/lib/postgresql/bin/postmaster
764 ? S 0:00 postgres: stats buffer process
765 ? S 0:00 postgres: stats collector process
10291 ? S 0:05 postgres: sd sd 10.2.1.5 idle in transaction
4303 ? S 0:00 postgres: sd sd 10.2.2.6 idle in transaction
4304 ? S 40:43 postgres: sd sd 10.2.2.6 idle in transaction
4370 ? S 2:54 postgres: sd sd 10.2.2.6 idle in transaction
4384 ? S 3:12 postgres: sd sd 10.2.2.6 idle in transaction
19961 ? S 4:32 postgres: sd sd 10.2.1.5 idle in transaction
19962 ? S 4:40 postgres: sd sd 10.2.1.5 idle in transaction
19963 ? S 4:24 postgres: sd sd 10.2.1.5 DELETE waiting
19964 ? S 4:58 postgres: sd sd 10.2.1.5 idle in transaction
19965 ? S 4:18 postgres: sd sd 10.2.1.5 idle in transaction
19966 ? S 3:49 postgres: sd sd 10.2.1.5 idle in transaction
5574 ? S 2:50 postgres: sd sd 10.2.1.5 idle in transaction
5575 ? S 2:54 postgres: sd sd 10.2.1.5 idle in transaction
8744 pts/0 S 0:00 /usr/lib/postgresql/bin/psql -d sd
8751 ? S 0:00 postgres: sd sd [local] idle
16606 ? S 0:03 postgres: sd sd 10.2.1.5 idle in transaction

To get rid of the problem we tried to upgrade to 7.3.3. But see next
mail for our experiences with 7.3.3.

-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 :

Philipp Reisner writes:

> Once in a while (about 3 times a day) one or more INSERTS/DELETES simply
> go into the "waiting" state, and block the whole database. The only way
> out is to terminate the client connection (i.e. to abort the blocked
> INSERT/DELETE query)
>
> Further investigation with ps -e -o wchan... showed that the backed
> process was simply sleeping in "semop".
>
> Output of ps:
>
> 762 ? S 0:00 /usr/lib/postgresql/bin/postmaster
> 764 ? S 0:00 postgres: stats buffer process
> 765 ? S 0:00 postgres: stats collector process
> 24872 ? S 0:00 postgres: sd sd 10.2.2.6 idle in transaction
> 24873 ? R 68:01 postgres: sd sd 10.2.2.6 SELECT
> 24932 ? S 3:09 postgres: sd sd 10.2.2.6 idle in transaction
> 24943 ? R 3:02 postgres: sd sd 10.2.2.6 SELECT
> 25004 ? S 0:01 postgres: sd sd 10.2.1.5 idle in transaction
[snip]

All these "idle in transaction" sessions have unfinished transactions that
are probably holding locks that the INSERT is waiting for. If you
constantly have loads of "idle in transaction" sessions, you need to fix
your application.

In 7.3 there is a system table called pg_locks that you can use to
investigate locks. I don't believe there was one in 7.2.

--
Peter Eisentraut peter_e(at)gmx(dot)net

Philipp Reisner <philipp(dot)reisner(at)linbit(dot)com> writes:

> 762 ? S 0:00 /usr/lib/postgresql/bin/postmaster
> 764 ? S 0:00 postgres: stats buffer process
> 765 ? S 0:00 postgres: stats collector process
> 24872 ? S 0:00 postgres: sd sd 10.2.2.6 idle in transaction
> 24873 ? R 68:01 postgres: sd sd 10.2.2.6 SELECT
> 24932 ? S 3:09 postgres: sd sd 10.2.2.6 idle in transaction
> 24943 ? R 3:02 postgres: sd sd 10.2.2.6 SELECT
> 25004 ? S 0:01 postgres: sd sd 10.2.1.5 idle in transaction
> 21226 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
> 21228 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
> 21229 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
> 21230 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
> 21231 ? S 0:01 postgres: sd sd 10.2.1.5 idle in transaction
> 21232 ? S 0:00 postgres: sd sd 10.2.1.5 idle in transaction
> 21227 ? S 0:01 postgres: sd sd 10.2.1.5 INSERT waiting
> 21391 pts/1 S 0:00 grep postg

I see no reason to think this is an undetected deadlock. The INSERT
is probably waiting for a lock that is held by one of your idle
transactions. You need to fix your client logic to not hold
transactions open for long periods.

(Now that you've moved up to 7.3, you could look at pg_locks to see just
which idle transaction is blocking the INSERT.)

regards, tom lane

Am Montag, 28. Juli 2003 11:41 schrieb Peter Eisentraut:
> Philipp Reisner writes:
> > Once in a while (about 3 times a day) one or more INSERTS/DELETES simply
> > go into the "waiting" state, and block the whole database. The only way
> > out is to terminate the client connection (i.e. to abort the blocked
> > INSERT/DELETE query)
> >
> > Further investigation with ps -e -o wchan... showed that the backed
> > process was simply sleeping in "semop".
> >
> > Output of ps:
> >
> > 762 ? S 0:00 /usr/lib/postgresql/bin/postmaster
> > 764 ? S 0:00 postgres: stats buffer process
> > 765 ? S 0:00 postgres: stats collector process
> > 24872 ? S 0:00 postgres: sd sd 10.2.2.6 idle in transaction
> > 24873 ? R 68:01 postgres: sd sd 10.2.2.6 SELECT
> > 24932 ? S 3:09 postgres: sd sd 10.2.2.6 idle in transaction
> > 24943 ? R 3:02 postgres: sd sd 10.2.2.6 SELECT
> > 25004 ? S 0:01 postgres: sd sd 10.2.1.5 idle in transaction
>
> [snip]
>
> All these "idle in transaction" sessions have unfinished transactions that
> are probably holding locks that the INSERT is waiting for. If you
> constantly have loads of "idle in transaction" sessions, you need to fix
> your application.
>
> In 7.3 there is a system table called pg_locks that you can use to
> investigate locks. I don't believe there was one in 7.2.

[ Sorry about this offtopic posting ]

Thanks a lot for the reply!

The applications uses the jdbc driver with autocommit turned off,
commit and rollback. Do you know if the jdbc driver just starts
a new transaction as soon as the last one was ended with commit/
rollback ?

BTW, The development system is still on postgres 7.3.3. The is
the pg_locks table:

relation | database | transaction | pid | mode | granted
----------+----------+-------------+-------+-----------------+---------
6520806 | 6520640 | | 20988 | AccessShareLock | t
| | 63435 | 21154 | ExclusiveLock | t
6521098 | 6520640 | | 20988 | AccessShareLock | t
6521041 | 6520640 | | 20988 | AccessShareLock | t
6520884 | 6520640 | | 20988 | AccessShareLock | t
6520894 | 6520640 | | 20988 | AccessShareLock | t
| | 63442 | 21153 | ExclusiveLock | t
| | 57548 | 21140 | ExclusiveLock | t
6520810 | 6520640 | | 20988 | AccessShareLock | t
| | 63434 | 21160 | ExclusiveLock | t
| | 63110 | 21109 | ExclusiveLock | t
6520833 | 6520640 | | 20988 | AccessShareLock | t
| | 57837 | 21096 | ExclusiveLock | t
6521078 | 6520640 | | 20988 | AccessShareLock | t
| | 63437 | 21156 | ExclusiveLock | t
6520702 | 6520640 | | 20988 | AccessShareLock | t
| | 63436 | 21155 | ExclusiveLock | t
| | 63438 | 21157 | ExclusiveLock | t
| | 63440 | 21159 | ExclusiveLock | t
6520814 | 6520640 | | 20988 | AccessShareLock | t
6520899 | 6520640 | | 20988 | AccessShareLock | t
6520652 | 6520640 | | 20988 | AccessShareLock | t
| | 57826 | 20987 | ExclusiveLock | t
| | 63439 | 21158 | ExclusiveLock | t
6521092 | 6520640 | | 20988 | AccessShareLock | t
16757 | 6520640 | | 21153 | AccessShareLock | t
| | 57535 | 20988 | ExclusiveLock | t
(27 rows)

-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 :

>
>
>
>Thanks a lot for the reply!
>
>The applications uses the jdbc driver with autocommit turned off,
>commit and rollback. Do you know if the jdbc driver just starts
>a new transaction as soon as the last one was ended with commit/
>rollback ?
>
>
Yes, it does.
You have to explictly setAutocommit(true) instead of commit() (or, you
can commit(), and *then* setAutocommit(true) if you want, the result is
the same).

I hope, it helps....

Dima

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 :

Philipp Reisner <philipp(dot)reisner(at)linbit(dot)com> writes:
> 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

> 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

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

Am Montag, 18. August 2003 15:38 schrieb Tom Lane:
> Philipp Reisner <philipp(dot)reisner(at)linbit(dot)com> writes:
> > 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
> >
> > 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
>
> 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

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 :

Am Dienstag, 19. August 2003 11:52 schrieb Philipp Reisner:
> Am Montag, 18. August 2003 15:38 schrieb Tom Lane:
> > Philipp Reisner <philipp(dot)reisner(at)linbit(dot)com> writes:
> > > 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
> > >
> > > 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
> >
> > 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
>
> 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

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