Mailing-List: contact derby-user-help@db.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Derby Discussion" <derby-user@db.apache.org>
Received-SPF: pass (nike.apache.org: local policy)
From: Andrew Lawrenson <andrew.lawrenson@coppereye.com>
To: Derby Discussion <derby-user@db.apache.org>
Date: Mon, 3 Mar 2008 04:59:42 -0500
Subject: RE: Derby, identity columns & locks on syscolumns
Thread-Topic: Derby, identity columns & locks on syscolumns
Thread-Index: Ach6wIb3m9g7qmWpQgyu9BOs6iQ57QAINp+QAIzChbA=
Message-ID: 
 <882C3355DFF9D3468379DD1E8C115FC713BE48714A@EVS-RED.coloflorida.com>
In-Reply-To: 
 <882C3355DFF9D3468379DD1E8C115FC713BE486911@EVS-RED.coloflorida.com>
Accept-Language: en-US
Content-Language: en-US
acceptlanguage: en-US
Content-Type: text/plain; charset="us-ascii"
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0

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 pa=
rent transaction - when this is done, I see none of the problems reported, =
and can have up to 100 concurrent threads inserting without any failing (wh=
ereas before this would instantly lock up).

So the question now is: "is the no-wait for the sub-transaction actually ne=
cessary?".

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 th=
ink 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:andrew.lawrenson@coppereye.com]
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 a=
bout 1/3 of a second).  Whilst the first transaction is locking syscolumns,=
 any other insert causing an update of the identity column will fail immedi=
ately, as the lock timeout is immediate for the sub-transaction.

When the sub-transactions fail, the updating of syscolumns is done under th=
e 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 o=
n the main transaction, eaching holding a lock on the index for their entir=
e transaction.

What I see is that when one update of syscolumns via the sub-transaction fa=
ils, the entire system locks up & most of the transactions inserting record=
s fail (as you suddenly get this cascade of locks being held), although onc=
e clients start failing the system gradually recovers.

So... Is this something I just have to live with, or is it an issue?  Any p=
otential workarounds that don't involve replacing identity columns with GUI=
Ds 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 colu=
mn on disk in the AUTOINCREMENTVALUE column of the SYS.SYSCOLUMNS system ta=
ble. Rolling back a transaction does not undo this value, and thus rolled-b=
ack transactions can leave "gaps" in the values automatically inserted into=
 an identity column. Derby behaves this way to avoid locking a row in SYS.S=
YSCOLUMNS 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 s=
yscolumns 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 sysco=
lumns by transaction A.
(Transaction A is itself blocked by an insert on another table - the same i=
ssue, which is why it hasn't committed)

Now, to me, this looks like the locks on syscolumns _are_ being held for th=
e duration of the transaction - is this correct, or is something else likel=
y 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 =3D 5599782), (S=
ESSIONID =3D 176), (DATABASE =3D DRSPRI), (DRDAID =3D null), Executing prep=
ared statement: insert into authorisation( authorisationtype, authorisednam=
e, userid, teamid, urnRef, reqRef, spocRef, reasonid, loggeddate, notes, re=
questmethod, status, lastuser, authorityid, authoritygroupid )  values (?,?=
,?,?,?,?,?,?,CURRENT_TIMESTAMP,?,?,?,?,?,? ) :End prepared statement with 1=
4 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 pa=
rameter #6:  :end parameter begin parameter #7:  :end parameter begin param=
eter #8: null :end parameter begin parameter #9:  :end parameter begin para=
meter #10:  :end parameter begin parameter #11: OPEN :end parameter begin p=
arameter #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 =3D 5599782), (S=
ESSIONID =3D 176), (DATABASE =3D DRSPRI), (DRDAID =3D null), Executing prep=
ared statement: VALUES IDENTITY_VAL_LOCAL() :End prepared statement

2008-02-29 09:36:53.704 GMT Thread[btpool0-108,5,main] (XID =3D 5599789), (=
SESSIONID =3D 173), (DATABASE =3D DRSPRI), (DRDAID =3D null), Executing pre=
pared statement: insert into authorisation( authorisationtype, authorisedna=
me, userid, teamid, urnRef, reqRef, spocRef, reasonid, loggeddate, notes, r=
equestmethod, status, lastuser, authorityid, authoritygroupid )  values (?,=
?,?,?,?,?,?,?,CURRENT_TIMESTAMP,?,?,?,?,?,? ) :End prepared statement with =
14 parameters begin parameter #1: 1 :end parameter begin parameter #2:  :en=
d parameter begin parameter #3: 611 :end parameter begin parameter #4: 101 =
:end parameter begin parameter #5: U1-1204278042611 :end parameter begin pa=
rameter #6:  :end parameter begin parameter #7:  :end parameter begin param=
eter #8: null :end parameter begin parameter #9:  :end parameter begin para=
meter #10:  :end parameter begin parameter #11: OPEN :end parameter begin p=
arameter #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 =3D 5599789), (=
SESSIONID =3D 173), (DATABASE =3D DRSPRI), (DRDAID =3D null), Failed Statem=
ent is: insert into authorisation( authorisationtype, authorisedname, useri=
d, teamid, urnRef, reqRef, spocRef, reasonid, loggeddate, notes, requestmet=
hod, status, lastuser, authorityid, authoritygroupid )  values (?,?,?,?,?,?=
,?,?,CURRENT_TIMESTAMP,?,?,?,?,?,? ) with 14 parameters begin parameter #1:=
 1 :end parameter begin parameter #2:  :end parameter begin parameter #3: 6=
11 :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 begi=
n 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 param=
eter

ERROR 40XL2: A lock could not be obtained within the time requested.  The l=
ockTable 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)  |TABLENAM=
E / CONGLOM_ID                |
---------------------------------------------------------------------------=
---------------------------------------------------------------------------=
---------------------------------------------------------------------------=
-------------------------------
*** The following row is the victim ***
5599789   |ROW          |X   |0        |(17,16)                            =
                                             |WAIT |S                      =
               |NULL                                              |SYSCOLUM=
NS                            |
*** The above row is the victim ***
5599782   |ROW          |X   |2        |(17,16)                            =
                                             |GRANT|S                      =
               |NULL                                              |SYSCOLUM=
NS                            |


Many thanks,

    Andrew Lawrenson