db-derby-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Andrew Lawrenson <andrew.lawren...@coppereye.com>
Subject RE: Derby, identity columns & locks on syscolumns
Date Fri, 29 Feb 2008 14:56:16 GMT
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:andrew.lawrenson@coppereye.com]
Sent: 29 February 2008 10:48
To: derby-user@db.apache.org
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




Mime
View raw message