We're using PostgreSQL to back tickets in CAS, http://www.jasig.org/cas,
in a large university environment where the ephemeral nature of CAS
tickets places a high concurrent read/write workload on the database.
We recently switched platforms from Oracle to PG and saw a dramatic
increase in deadlocks for the following workflow executed concurrently:
1. Begin transaction
2. Create ticket (INSERT INTO SERVICETICKET...)
3. Update parent ticket-granting ticket (UPDATE TICKETGRANTINGTICKET...)
4. Commit
The following postgres logs provide a detailed example of two deadlocked
transactions:
=====================================
BLOCKED Transaction
=====================================
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_creat" (OID 957)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_open" (OID 952)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lowrite" (OID 955)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_close" (OID 953)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_creat" (OID 957)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_open" (OID 952)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lowrite" (OID 955)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_close" (OID 953)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 PARSE LOG: duration: 0.000 ms parse <unnamed>: insert
into SERVICETICKET (NUMBER_OF_TIMES_USED, CREATION_TIME,
EXPIRATION_POLICY, LAST_TIME_USED, PREVIOUS_LAST_TIME_USED,
ticketGrantingTicket_ID, FROM_NEW_LOGIN, TICKET_ALREADY_GRANTED,
SERVICE, ID) values ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 BIND LOG: duration: 0.000 ms bind <unnamed>: insert
into SERVICETICKET (NUMBER_OF_TIMES_USED, CREATION_TIME,
EXPIRATION_POLICY, LAST_TIME_USED, PREVIOUS_LAST_TIME_USED,
ticketGrantingTicket_ID, FROM_NEW_LOGIN, TICKET_ALREADY_GRANTED,
SERVICE, ID) values ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 BIND DETAIL: parameters: $1 = '0', $2 =
'1276614383240', $3 = '3535872', $4 = '1276614383240', $5 = '0', $6 =
'TGT-198041-jErDe9IINT5toBTOKtgNt1EQ9JUk6pcsvQDgO93UkidCj7WIpp-auth-2',
$7 = 'f', $8 = 'f', $9 = '3535873', $10 =
'ST-205046-96V10UhgRMePGqkCAEOo-auth-2'
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 INSERT LOG: duration: 0.000 ms execute <unnamed>:
insert into SERVICETICKET (NUMBER_OF_TIMES_USED, CREATION_TIME,
EXPIRATION_POLICY, LAST_TIME_USED, PREVIOUS_LAST_TIME_USED,
ticketGrantingTicket_ID, FROM_NEW_LOGIN, TICKET_ALREADY_GRANTED,
SERVICE, ID) values ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 INSERT DETAIL: parameters: $1 = '0', $2 =
'1276614383240', $3 = '3535872', $4 = '1276614383240', $5 = '0', $6 =
'TGT-198041-jErDe9IINT5toBTOKtgNt1EQ9JUk6pcsvQDgO93UkidCj7WIpp-auth-2',
$7 = 'f', $8 = 'f', $9 = '3535873', $10 =
'ST-205046-96V10UhgRMePGqkCAEOo-auth-2'
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_creat" (OID 957)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_open" (OID 952)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lowrite" (OID 955)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_close" (OID 953)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_creat" (OID 957)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_open" (OID 952)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lowrite" (OID 955)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_close" (OID 953)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_creat" (OID 957)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_open" (OID 952)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lowrite" (OID 955)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_close" (OID 953)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 PARSE LOG: duration: 0.000 ms parse <unnamed>: update
TICKETGRANTINGTICKET set NUMBER_OF_TIMES_USED=$1, CREATION_TIME=$2,
EXPIRATION_POLICY=$3, LAST_TIME_USED=$4, PREVIOUS_LAST_TIME_USED=$5,
ticketGrantingTicket_ID=$6, AUTHENTICATION=$7, EXPIRED=$8,
SERVICES_GRANTED_ACCESS_TO=$9 where ID=$10
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 BIND LOG: duration: 0.000 ms bind <unnamed>: update
TICKETGRANTINGTICKET set NUMBER_OF_TIMES_USED=$1, CREATION_TIME=$2,
EXPIRATION_POLICY=$3, LAST_TIME_USED=$4, PREVIOUS_LAST_TIME_USED=$5,
ticketGrantingTicket_ID=$6, AUTHENTICATION=$7, EXPIRED=$8,
SERVICES_GRANTED_ACCESS_TO=$9 where ID=$10
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 BIND DETAIL: parameters: $1 = '2', $2 =
'1276609420364', $3 = '3535876', $4 = '1276614383240', $5 =
'1276609420388', $6 = NULL, $7 = '3535877', $8 = 'f', $9 = '3535879',
$10 = 'TGT-198041-jErDe9IINT5toBTOKtgNt1EQ9JUk6pcsvQDgO93UkidCj7WIpp-auth-2'
2010-06-15 11:06:24 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 UPDATE ERROR: deadlock detected
2010-06-15 11:06:24 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 UPDATE DETAIL: Process 20787 waits for ShareLock on
transaction 3335054; blocked by process 16175.
2010-06-15 11:06:24 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 UPDATE HINT: See server log for query details.
2010-06-15 11:06:24 EDT cas 198.82.164.234 cas_user 4c17957b.5133
5/696029 3335052 UPDATE STATEMENT: update TICKETGRANTINGTICKET set
NUMBER_OF_TIMES_USED=$1, CREATION_TIME=$2, EXPIRATION_POLICY=$3,
LAST_TIME_USED=$4, PREVIOUS_LAST_TIME_USED=$5,
ticketGrantingTicket_ID=$6, AUTHENTICATION=$7, EXPIRED=$8,
SERVICES_GRANTED_ACCESS_TO=$9 where ID=$10
2010-06-15 11:06:24 EDT cas 198.82.164.234 cas_user 4c17957b.5133 5/0
3335052 PARSE ERROR: current transaction is aborted, commands ignored
until end of transaction block
2010-06-15 11:06:24 EDT cas 198.82.164.234 cas_user 4c17957b.5133 5/0
3335052 PARSE STATEMENT: select 1
2010-06-15 11:06:24 EDT cas 198.82.164.234 cas_user 4c17957b.5133 5/0
3335052 PARSE LOG: duration: 0.000 ms parse S_3: ROLLBACK
2010-06-15 11:06:24 EDT cas 198.82.164.234 cas_user 4c17957b.5133 5/0
3335052 BIND LOG: duration: 0.000 ms bind S_3: ROLLBACK
=====================================
BLOCKING Transaction
=====================================
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_creat" (OID 957)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_open" (OID 952)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lowrite" (OID 955)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_close" (OID 953)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_creat" (OID 957)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_open" (OID 952)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lowrite" (OID 955)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_close" (OID 953)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 PARSE LOG: duration: 0.000 ms parse <unnamed>:
insert into SERVICETICKET (NUMBER_OF_TIMES_USED, CREATION_TIME,
EXPIRATION_POLICY, LAST_TIME_USED, PREVIOUS_LAST_TIME_USED,
ticketGrantingTicket_ID, FROM_NEW_LOGIN, TICKET_ALREADY_GRANTED,
SERVICE, ID) values ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 BIND LOG: duration: 0.000 ms bind <unnamed>: insert
into SERVICETICKET (NUMBER_OF_TIMES_USED, CREATION_TIME,
EXPIRATION_POLICY, LAST_TIME_USED, PREVIOUS_LAST_TIME_USED,
ticketGrantingTicket_ID, FROM_NEW_LOGIN, TICKET_ALREADY_GRANTED,
SERVICE, ID) values ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 BIND DETAIL: parameters: $1 = '0', $2 =
'1276614383244', $3 = '3535874', $4 = '1276614383244', $5 = '0', $6 =
'TGT-198041-jErDe9IINT5toBTOKtgNt1EQ9JUk6pcsvQDgO93UkidCj7WIpp-auth-2',
$7 = 'f', $8 = 'f', $9 = '3535875', $10 =
'ST-205047-vK1YftWSDBHxOKQhDzdJ-auth-2'
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 INSERT LOG: duration: 0.000 ms execute <unnamed>:
insert into SERVICETICKET (NUMBER_OF_TIMES_USED, CREATION_TIME,
EXPIRATION_POLICY, LAST_TIME_USED, PREVIOUS_LAST_TIME_USED,
ticketGrantingTicket_ID, FROM_NEW_LOGIN, TICKET_ALREADY_GRANTED,
SERVICE, ID) values ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 INSERT DETAIL: parameters: $1 = '0', $2 =
'1276614383244', $3 = '3535874', $4 = '1276614383244', $5 = '0', $6 =
'TGT-198041-jErDe9IINT5toBTOKtgNt1EQ9JUk6pcsvQDgO93UkidCj7WIpp-auth-2',
$7 = 'f', $8 = 'f', $9 = '3535875', $10 =
'ST-205047-vK1YftWSDBHxOKQhDzdJ-auth-2'
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_creat" (OID 957)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_open" (OID 952)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lowrite" (OID 955)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_close" (OID 953)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_creat" (OID 957)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_open" (OID 952)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lowrite" (OID 955)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_close" (OID 953)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_creat" (OID 957)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_open" (OID 952)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lowrite" (OID 955)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 idle in transaction LOG: duration: 0.000 ms fastpath
function call: "lo_close" (OID 953)
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 PARSE LOG: duration: 0.000 ms parse <unnamed>:
update TICKETGRANTINGTICKET set NUMBER_OF_TIMES_USED=$1,
CREATION_TIME=$2, EXPIRATION_POLICY=$3, LAST_TIME_USED=$4,
PREVIOUS_LAST_TIME_USED=$5, ticketGrantingTicket_ID=$6,
AUTHENTICATION=$7, EXPIRED=$8, SERVICES_GRANTED_ACCESS_TO=$9 where ID=$10
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 BIND LOG: duration: 0.000 ms bind <unnamed>: update
TICKETGRANTINGTICKET set NUMBER_OF_TIMES_USED=$1, CREATION_TIME=$2,
EXPIRATION_POLICY=$3, LAST_TIME_USED=$4, PREVIOUS_LAST_TIME_USED=$5,
ticketGrantingTicket_ID=$6, AUTHENTICATION=$7, EXPIRED=$8,
SERVICES_GRANTED_ACCESS_TO=$9 where ID=$10
2010-06-15 11:06:23 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 BIND DETAIL: parameters: $1 = '2', $2 =
'1276609420364', $3 = '3535878', $4 = '1276614383244', $5 =
'1276609420388', $6 = NULL, $7 = '3535880', $8 = 'f', $9 = '3535881',
$10 = 'TGT-198041-jErDe9IINT5toBTOKtgNt1EQ9JUk6pcsvQDgO93UkidCj7WIpp-auth-2'
2010-06-15 11:06:24 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 UPDATE LOG: duration: 996.023 ms execute <unnamed>:
update TICKETGRANTINGTICKET set NUMBER_OF_TIMES_USED=$1,
CREATION_TIME=$2, EXPIRATION_POLICY=$3, LAST_TIME_USED=$4,
PREVIOUS_LAST_TIME_USED=$5, ticketGrantingTicket_ID=$6,
AUTHENTICATION=$7, EXPIRED=$8, SERVICES_GRANTED_ACCESS_TO=$9 where ID=$10
2010-06-15 11:06:24 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 UPDATE DETAIL: parameters: $1 = '2', $2 =
'1276609420364', $3 = '3535878', $4 = '1276614383244', $5 =
'1276609420388', $6 = NULL, $7 = '3535880', $8 = 'f', $9 = '3535881',
$10 = 'TGT-198041-jErDe9IINT5toBTOKtgNt1EQ9JUk6pcsvQDgO93UkidCj7WIpp-auth-2'
2010-06-15 11:06:24 EDT cas 198.82.164.234 cas_user 4c178ae4.3f2f
11/510008 3335054 BIND LOG: duration: 0.000 ms bind S_2: COMMIT
======================
To help investigate the problem we developed a test script to force
concurrent writes of this kind and were able to reliably reproduce the
problem. Ultimately we discovered that dropping the foreign key
constraint from SERVICETICKET to TICKETGRANTINGTICKET completely
resolved the issue, presumably because it removed the need to obtain a
ShareLock on TICKETGRANTINGTICKET. This is an acceptable solution in
our case, but unideal since it may require out-of-band scripts to clean
up orphaned tickets.
My impression at present is that the fundamental locking behavior of
PostgreSQL is poorly suited to applications that have both great deals
of concurrency and referential integrity. This is of concern to us as
we are considering migrating to PostgreSQL from Oracle for other
applications. I realize that application design changes could possibly
mitigate this problem, but I would argue that this case is so common
that it ought to be handled better.
I would sincerely appreciate opinions on whether parent-child locking
semantics are as troubled as I'm suggesting. Are there any plans to
change/improve the behavior? (I carefully reviewed the v9 release notes
and didn't see mention of this issue.) I would be pleased to
collaborate on changes in this area -- we have a sound test harness to
evaluate potential improvements.
Thanks,
Marvin Addison
Middleware Services
Virginia Tech
--
Sent via pgsql-general mailing list (pgsql-general@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
