I think I've found my own answer:
When the updating of identity column is done, a sub-transaction is started for
updating syscolumns. This transaction normally (for me) lasts at most 1ms.
However, sometimes under a heavy load, it's taken longer (I've seen about 1/3
of a second). Whilst the first transaction is locking syscolumns, any other
insert causing an update of the identity column will fail immediately, as the
lock timeout is immediate for the sub-transaction.
When the sub-transactions fail, the updating of syscolumns is done under the
parent transaction - which may not be committed for several seconds (for me,
under heavy load). And during this time, of course, all other inserts will
start failing under the sub-transactions, which then get re-executed on the
main transaction, eaching holding a lock on the index for their entire
transaction.
What I see is that when one update of syscolumns via the sub-transaction fails,
the entire system locks up & most of the transactions inserting records fail
(as you suddenly get this cascade of locks being held), although once clients
start failing the system gradually recovers.
So... Is this something I just have to live with, or is it an issue? Any
potential workarounds that don't involve replacing identity columns with GUIDs
or similar?
thanks in advance,
Andrew Lawrenson
-----Original Message-----
From: Andrew Lawrenson [mailto:[EMAIL PROTECTED]
Sent: 29 February 2008 10:48
To: [email protected]
Subject: Derby, identity columns & locks on syscolumns
Hi all,
as I understand it, when you insert a row into a table with an identity
column, it has to lock syscolumns to update the identity value - from the docs:
"Derby keeps track of the last increment value for a column in a cache. It also
stores the value of what the next increment value will be for the column on
disk in the AUTOINCREMENTVALUE column of the SYS.SYSCOLUMNS system table.
Rolling back a transaction does not undo this value, and thus rolled-back
transactions can leave "gaps" in the values automatically inserted into an
identity column. Derby behaves this way to avoid locking a row in
SYS.SYSCOLUMNS for the duration of a transaction and keeping concurrency high."
However, what I'm seeing looks like a row is being locked in sys.syscolumns for
the duration of the transaction.
When performing lots of inserts in parallel, I'm getting lock timeouts on
syscolumns for the inserts, e.g.:
transaction A performs an insert in table T1.
transaction B performs an insert in table T1.
1 minute later, transaction B fails, due to an exclusive lock held on
syscolumns by transaction A.
(Transaction A is itself blocked by an insert on another table - the same
issue, which is why it hasn't committed)
Now, to me, this looks like the locks on syscolumns _are_ being held for the
duration of the transaction - is this correct, or is something else likely to
be to blame?
This is using Derby 10.3.2.1 on Solaris 10 (x86).
Exerpts from the derby log file are as follows:
2008-02-29 09:36:53.652 GMT Thread[btpool0-77,5,main] (XID = 5599782),
(SESSIONID = 176), (DATABASE = DRSPRI), (DRDAID = null), Executing prepared
statement: insert into authorisation( authorisationtype, authorisedname,
userid, teamid, urnRef, reqRef, spocRef, reasonid, loggeddate, notes,
requestmethod, status, lastuser, authorityid, authoritygroupid ) values
(?,?,?,?,?,?,?,?,CURRENT_TIMESTAMP,?,?,?,?,?,? ) :End prepared statement with
14 parameters begin parameter #1: 1 :end parameter begin parameter #2: :end
parameter begin parameter #3: 611 :end parameter begin parameter #4: 101 :end
parameter begin parameter #5: U15-1204277813126 :end parameter begin parameter
#6: :end parameter begin parameter #7: :end parameter begin parameter #8:
null :end parameter begin parameter #9: :end parameter begin parameter #10:
:end parameter begin parameter #11: OPEN :end parameter begin parameter #12:
611 :end parameter begin parameter #13: 10000 :end parameter begin parameter
#14: 1 :end parameter
2008-02-29 09:36:53.658 GMT Thread[btpool0-77,5,main] (XID = 5599782),
(SESSIONID = 176), (DATABASE = DRSPRI), (DRDAID = null), Executing prepared
statement: VALUES IDENTITY_VAL_LOCAL() :End prepared statement
2008-02-29 09:36:53.704 GMT Thread[btpool0-108,5,main] (XID = 5599789),
(SESSIONID = 173), (DATABASE = DRSPRI), (DRDAID = null), Executing prepared
statement: insert into authorisation( authorisationtype, authorisedname,
userid, teamid, urnRef, reqRef, spocRef, reasonid, loggeddate, notes,
requestmethod, status, lastuser, authorityid, authoritygroupid ) values
(?,?,?,?,?,?,?,?,CURRENT_TIMESTAMP,?,?,?,?,?,? ) :End prepared statement with
14 parameters begin parameter #1: 1 :end parameter begin parameter #2: :end
parameter begin parameter #3: 611 :end parameter begin parameter #4: 101 :end
parameter begin parameter #5: U1-1204278042611 :end parameter begin parameter
#6: :end parameter begin parameter #7: :end parameter begin parameter #8:
null :end parameter begin parameter #9: :end parameter begin parameter #10:
:end parameter begin parameter #11: OPEN :end parameter begin parameter #12:
611 :end parameter begin parameter #13: 10000 :end parameter begin parameter
#14: 1 :end parameter
2008-02-29 09:37:53.819 GMT Thread[btpool0-108,5,main] (XID = 5599789),
(SESSIONID = 173), (DATABASE = DRSPRI), (DRDAID = null), Failed Statement is:
insert into authorisation( authorisationtype, authorisedname, userid, teamid,
urnRef, reqRef, spocRef, reasonid, loggeddate, notes, requestmethod, status,
lastuser, authorityid, authoritygroupid ) values
(?,?,?,?,?,?,?,?,CURRENT_TIMESTAMP,?,?,?,?,?,? ) with 14 parameters begin
parameter #1: 1 :end parameter begin parameter #2: :end parameter begin
parameter #3: 611 :end parameter begin parameter #4: 101 :end parameter begin
parameter #5: U1-1204278042611 :end parameter begin parameter #6: :end
parameter begin parameter #7: :end parameter begin parameter #8: null :end
parameter begin parameter #9: :end parameter begin parameter #10: :end
parameter begin parameter #11: OPEN :end parameter begin parameter #12: 611
:end parameter begin parameter #13: 10000 :end parameter begin parameter #14: 1
:end parameter
ERROR 40XL2: A lock could not be obtained within the time requested. The
lockTable dump is:
2008-02-29 09:37:53.737 GMT
XID |TYPE |MODE|LOCKCOUNT|LOCKNAME
|STATE|TABLETYPE / LOCKOBJ
|INDEXNAME / CONTAINER_ID / (MODE for LATCH only) |TABLENAME / CONGLOM_ID
|
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
*** The following row is the victim ***
5599789 |ROW |X |0 |(17,16)
|WAIT |S
|NULL |SYSCOLUMNS
|
*** The above row is the victim ***
5599782 |ROW |X |2 |(17,16)
|GRANT|S
|NULL |SYSCOLUMNS
|
Many thanks,
Andrew Lawrenson
