I've done some more experimentation & testing.
At the moment, when syscolumns is updated, if a sub-transction is done, the
update is done with an expicit no-wait on locks.
I've tried changing this so that it will use the same wait policy as the parent
transaction - when this is done, I see none of the problems reported, and can
have up to 100 concurrent threads inserting without any failing (whereas before
this would instantly lock up).
So the question now is: "is the no-wait for the sub-transaction actually
necessary?".
Personally, I can't see why it is, although I'm not exactly a guru at derby
internals. If the reason why is simply to increase concurrency, then I think
it's flawed, as it forces more updates to be carried out by the parent
transaction, which will hold the lock much longer before committing...
Any ideas? Or is this the wrong list to be asking - should I pose this on
derby-developers instead?
Many thanks,
Andrew Lawrenson
-----Original Message-----
From: Andrew Lawrenson [mailto:[EMAIL PROTECTED]
Sent: 29 February 2008 14:56
To: Derby Discussion
Subject: RE: Derby, identity columns & locks on syscolumns
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
