locking problem

[rjcarr]

super short summary:

I'm getting this exception when trying to run an update:

"a lock could not be obtained within the time requested"

Looking around various forums it seems I might have a transaction that
didn't complete, but I can't track it down.  Any suggestion on how to
do so?  Is there a way to get a list of all the (preferably pending)
transactions?

slightly more details:

I've used this page quite a bit for help, and it gave me some hints,
but nothing conclusive:

http://wiki.apache.org/db-derby/LockDebugging

Derby is being used in an embedded environment and it is single-threaded.

Using the derby.locks.deadlockTrace it says there is a WAIT lock on a
table.  After the wait time it seems to resolve itself and continues
to work as expected.  After it finishes, checking the lock table again
(using select * from syscs_diag.lock_table) there are only GRANT locks
(however, checking the table before the problem there are no entries
in the table).

gory details:

I have an application where I parse a number of files in a folder and
put the contents into a database.  As time goes on new files may be
added to this folder, and some time later I rescan the folder and
reenter the data (relying on uniqueness constraints to avoid duplicate
data).  If I get a uniqueness exception I do an update on the row that
was already in the database.  Here's what's happening ...

If my folder initially has 10 files all of the data goes in fine.
Some time later, my folder might have 20 files, and it is rescanned.
The first 9 files are rescanned and then updated when there's a
duplicate without problem.  Then, the 10th file blocks on this lock, a
minute later I get the exception, and then the remaining 10 files are
successfully entered into the database.

If I instead had 5 files initially and 10 files later, it would
instead block on rescanning the 5th file.  It *always* blocks on the
*last* previously scanned file.  All previously scanned files are
updated without a problem, and all unscanned files are then
successfully scanned.

However, after the initial scan the lock table is empty ... there are
no lingering locks whatsoever.

The failed insert and subsequent update (attempt) are using the same
connection.  Auto commit is set to true.

Any ideas?

Thanks-
Robert

[Jeff Stuckman]

Hello Robert,

What version of Derby are you using?

Jeff

-----Original Message-----
From: Robert J. Carr [mailto:rjcarr@...]
Sent: Wednesday, July 01, 2009 11:56 PM
To: Derby Discussion
Subject: locking problem

super short summary:

I'm getting this exception when trying to run an update:

"a lock could not be obtained within the time requested"

Looking around various forums it seems I might have a transaction that
didn't complete, but I can't track it down.  Any suggestion on how to
do so?  Is there a way to get a list of all the (preferably pending)
transactions?

slightly more details:

I've used this page quite a bit for help, and it gave me some hints,
but nothing conclusive:

http://wiki.apache.org/db-derby/LockDebugging

Derby is being used in an embedded environment and it is single-threaded.

Using the derby.locks.deadlockTrace it says there is a WAIT lock on a
table.  After the wait time it seems to resolve itself and continues
to work as expected.  After it finishes, checking the lock table again
(using select * from syscs_diag.lock_table) there are only GRANT locks
(however, checking the table before the problem there are no entries
in the table).

gory details:

I have an application where I parse a number of files in a folder and
put the contents into a database.  As time goes on new files may be
added to this folder, and some time later I rescan the folder and
reenter the data (relying on uniqueness constraints to avoid duplicate
data).  If I get a uniqueness exception I do an update on the row that
was already in the database.  Here's what's happening ...

If my folder initially has 10 files all of the data goes in fine.
Some time later, my folder might have 20 files, and it is rescanned.
The first 9 files are rescanned and then updated when there's a
duplicate without problem.  Then, the 10th file blocks on this lock, a
minute later I get the exception, and then the remaining 10 files are
successfully entered into the database.

If I instead had 5 files initially and 10 files later, it would
instead block on rescanning the 5th file.  It *always* blocks on the
*last* previously scanned file.  All previously scanned files are
updated without a problem, and all unscanned files are then
successfully scanned.

However, after the initial scan the lock table is empty ... there are
no lingering locks whatsoever.

The failed insert and subsequent update (attempt) are using the same
connection.  Auto commit is set to true.

Any ideas?

Thanks-
Robert

[rjcarr]

Hi Jeff-

It initially happened in 10.3.2.1, but I just updated to 10.5.1.1 and
the same problem exists.

And I may have mentioned in the original post it was a table lock, and
I don't know if I misread it initially or if something changed when I
updated derby, but it seems to be a row lock.  Here's a condensed
version of the lock trace:

java.sql.SQLException: A lock could not be obtained within the time
requested.  The lockTable dump is:
XID       |TYPE   |MODE |LOCKCOUNT |LOCKNAME   |STATE |TABLENAME
----------------------------------------------------------------
*** The following row is the victim ***
5222      |ROW    |X    |0         |(2,38)     |WAIT  |SG_TRACKS
*** The above row is the victim ***
5104      |ROW    |S    |1         |(2,38)     |GRANT |SG_TRACKS
5104      |TABLE  |IS   |1         |Tablelock  |GRANT |SG_TRACKS
5222      |TABLE  |IX   |2         |Tablelock  |GRANT |SG_TRACKS
----------------------------------------------------------------
        at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown
Source)
        at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)
        at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown
Source)
        at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown
Source)
        at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
        at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
        at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
        at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown
Source)
        at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeUpdate(Unknown
Source)

Thanks-
Robert

On Thu, Jul 2, 2009 at 11:02 AM, Jeff Stuckman<stuckman@...> wrote:

> Hello Robert,
>
> What version of Derby are you using?
>
> Jeff
>
> -----Original Message-----
> From: Robert J. Carr [mailto:rjcarr@...]
> Sent: Wednesday, July 01, 2009 11:56 PM
> To: Derby Discussion
> Subject: locking problem
>
> super short summary:
>
> I'm getting this exception when trying to run an update:
>
> "a lock could not be obtained within the time requested"
>
> Looking around various forums it seems I might have a transaction that
> didn't complete, but I can't track it down.  Any suggestion on how to
> do so?  Is there a way to get a list of all the (preferably pending)
> transactions?
>
> slightly more details:
>
> I've used this page quite a bit for help, and it gave me some hints,
> but nothing conclusive:
>
> http://wiki.apache.org/db-derby/LockDebugging
>
> Derby is being used in an embedded environment and it is single-threaded.
>
> Using the derby.locks.deadlockTrace it says there is a WAIT lock on a
> table.  After the wait time it seems to resolve itself and continues
> to work as expected.  After it finishes, checking the lock table again
> (using select * from syscs_diag.lock_table) there are only GRANT locks
> (however, checking the table before the problem there are no entries
> in the table).
>
> gory details:
>
> I have an application where I parse a number of files in a folder and
> put the contents into a database.  As time goes on new files may be
> added to this folder, and some time later I rescan the folder and
> reenter the data (relying on uniqueness constraints to avoid duplicate
> data).  If I get a uniqueness exception I do an update on the row that
> was already in the database.  Here's what's happening ...
>
> If my folder initially has 10 files all of the data goes in fine.
> Some time later, my folder might have 20 files, and it is rescanned.
> The first 9 files are rescanned and then updated when there's a
> duplicate without problem.  Then, the 10th file blocks on this lock, a
> minute later I get the exception, and then the remaining 10 files are
> successfully entered into the database.
>
> If I instead had 5 files initially and 10 files later, it would
> instead block on rescanning the 5th file.  It *always* blocks on the
> *last* previously scanned file.  All previously scanned files are
> updated without a problem, and all unscanned files are then
> successfully scanned.
>
> However, after the initial scan the lock table is empty ... there are
> no lingering locks whatsoever.
>
> The failed insert and subsequent update (attempt) are using the same
> connection.  Auto commit is set to true.
>
> Any ideas?
>
> Thanks-
> Robert
>
>
>

[francois.orsini]

Hi Robert,

Your application is not setting some particular transaction isolation level _explicitly_ by any chance?

http://db.apache.org/derby/docs/dev/devguide/cdevconcepts15366.html

The default value for derby.locks.waitTimeout property is 60 seconds.
http://db.apache.org/derby/docs/dev/devguide/cdevconcepts16400.html

--francois

On Thu, Jul 2, 2009 at 11:08 AM, Robert J. Carr <rjcarr@...> wrote:

Hi Jeff-

It initially happened in 10.3.2.1, but I just updated to 10.5.1.1 and
the same problem exists.

And I may have mentioned in the original post it was a table lock, and
I don't know if I misread it initially or if something changed when I
updated derby, but it seems to be a row lock.  Here's a condensed
version of the lock trace:

java.sql.SQLException: A lock could not be obtained within the time
requested.  The lockTable dump is:
XID       |TYPE   |MODE |LOCKCOUNT |LOCKNAME   |STATE |TABLENAME
----------------------------------------------------------------
*** The following row is the victim ***
5222      |ROW    |X    |0         |(2,38)     |WAIT  |SG_TRACKS
*** The above row is the victim ***
5104      |ROW    |S    |1         |(2,38)     |GRANT |SG_TRACKS
5104      |TABLE  |IS   |1         |Tablelock  |GRANT |SG_TRACKS
5222      |TABLE  |IX   |2         |Tablelock  |GRANT |SG_TRACKS
----------------------------------------------------------------
       at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown
Source)
       at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)
       at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown
Source)
       at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown
Source)
       at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
       at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
       at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
       at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown
Source)
       at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeUpdate(Unknown
Source)

Thanks-
Robert

On Thu, Jul 2, 2009 at 11:02 AM, Jeff Stuckman<stuckman@...> wrote:
> Hello Robert,
>
> What version of Derby are you using?
>
> Jeff
>
> -----Original Message-----
> From: Robert J. Carr [mailto:rjcarr@...]
> Sent: Wednesday, July 01, 2009 11:56 PM
> To: Derby Discussion
> Subject: locking problem
>
> super short summary:
>
> I'm getting this exception when trying to run an update:
>
> "a lock could not be obtained within the time requested"
>
> Looking around various forums it seems I might have a transaction that
> didn't complete, but I can't track it down.  Any suggestion on how to
> do so?  Is there a way to get a list of all the (preferably pending)
> transactions?
>
> slightly more details:
>
> I've used this page quite a bit for help, and it gave me some hints,
> but nothing conclusive:
>
> http://wiki.apache.org/db-derby/LockDebugging
>
> Derby is being used in an embedded environment and it is single-threaded.
>
> Using the derby.locks.deadlockTrace it says there is a WAIT lock on a
> table.  After the wait time it seems to resolve itself and continues
> to work as expected.  After it finishes, checking the lock table again
> (using select * from syscs_diag.lock_table) there are only GRANT locks
> (however, checking the table before the problem there are no entries
> in the table).
>
> gory details:
>
> I have an application where I parse a number of files in a folder and
> put the contents into a database.  As time goes on new files may be
> added to this folder, and some time later I rescan the folder and
> reenter the data (relying on uniqueness constraints to avoid duplicate
> data).  If I get a uniqueness exception I do an update on the row that
> was already in the database.  Here's what's happening ...
>
> If my folder initially has 10 files all of the data goes in fine.
> Some time later, my folder might have 20 files, and it is rescanned.
> The first 9 files are rescanned and then updated when there's a
> duplicate without problem.  Then, the 10th file blocks on this lock, a
> minute later I get the exception, and then the remaining 10 files are
> successfully entered into the database.
>
> If I instead had 5 files initially and 10 files later, it would
> instead block on rescanning the 5th file.  It *always* blocks on the
> *last* previously scanned file.  All previously scanned files are
> updated without a problem, and all unscanned files are then
> successfully scanned.
>
> However, after the initial scan the lock table is empty ... there are
> no lingering locks whatsoever.
>
> The failed insert and subsequent update (attempt) are using the same
> connection.  Auto commit is set to true.
>
> Any ideas?
>
> Thanks-
> Robert
>
>
>

[rjcarr]

Hi Francois-

Nope, there are no explicit isolation levels.  Everything is about as
vanilla (basic, default) as possible.

I'm not sure why you mention the wait timeout, but yes, it takes 60
seconds to raise the exception, then it finishes the rest of the work
normally and without problem.

I should also mention there are no locking issues in mysql.  It
doesn't mean it is a derby bug, in fact, I'm reasonably sure derby is
showing me a symptom of a problem, just that mysql never gets stuck on
a lock.

Thanks-
Robert

On Thu, Jul 2, 2009 at 5:05 PM, Francois
Orsini<francois.orsini@...> wrote:

> Hi Robert,
>
> Your application is not setting some particular transaction isolation level
> _explicitly_ by any chance?
>
> http://db.apache.org/derby/docs/dev/devguide/cdevconcepts15366.html
>
> The default value for derby.locks.waitTimeout property is 60 seconds.
> http://db.apache.org/derby/docs/dev/devguide/cdevconcepts16400.html
>
> --francois
>
> On Thu, Jul 2, 2009 at 11:08 AM, Robert J. Carr <rjcarr@...> wrote:
>>
>> Hi Jeff-
>>
>> It initially happened in 10.3.2.1, but I just updated to 10.5.1.1 and
>> the same problem exists.
>>
>> And I may have mentioned in the original post it was a table lock, and
>> I don't know if I misread it initially or if something changed when I
>> updated derby, but it seems to be a row lock.  Here's a condensed
>> version of the lock trace:
>>
>> java.sql.SQLException: A lock could not be obtained within the time
>> requested.  The lockTable dump is:
>> XID       |TYPE   |MODE |LOCKCOUNT |LOCKNAME   |STATE |TABLENAME
>> ----------------------------------------------------------------
>> *** The following row is the victim ***
>> 5222      |ROW    |X    |0         |(2,38)     |WAIT  |SG_TRACKS
>> *** The above row is the victim ***
>> 5104      |ROW    |S    |1         |(2,38)     |GRANT |SG_TRACKS
>> 5104      |TABLE  |IS   |1         |Tablelock  |GRANT |SG_TRACKS
>> 5222      |TABLE  |IX   |2         |Tablelock  |GRANT |SG_TRACKS
>> ----------------------------------------------------------------
>>        at
>> org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown
>> Source)
>>        at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown
>> Source)
>>        at
>> org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown
>> Source)
>>        at
>> org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown
>> Source)
>>        at
>> org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
>>        at
>> org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
>>        at
>> org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
>>        at
>> org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown
>> Source)
>>        at
>> org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeUpdate(Unknown
>> Source)
>>
>> Thanks-
>> Robert
>>
>> On Thu, Jul 2, 2009 at 11:02 AM, Jeff Stuckman<stuckman@...> wrote:
>> > Hello Robert,
>> >
>> > What version of Derby are you using?
>> >
>> > Jeff
>> >
>> > -----Original Message-----
>> > From: Robert J. Carr [mailto:rjcarr@...]
>> > Sent: Wednesday, July 01, 2009 11:56 PM
>> > To: Derby Discussion
>> > Subject: locking problem
>> >
>> > super short summary:
>> >
>> > I'm getting this exception when trying to run an update:
>> >
>> > "a lock could not be obtained within the time requested"
>> >
>> > Looking around various forums it seems I might have a transaction that
>> > didn't complete, but I can't track it down.  Any suggestion on how to
>> > do so?  Is there a way to get a list of all the (preferably pending)
>> > transactions?
>> >
>> > slightly more details:
>> >
>> > I've used this page quite a bit for help, and it gave me some hints,
>> > but nothing conclusive:
>> >
>> > http://wiki.apache.org/db-derby/LockDebugging
>> >
>> > Derby is being used in an embedded environment and it is
>> > single-threaded.
>> >
>> > Using the derby.locks.deadlockTrace it says there is a WAIT lock on a
>> > table.  After the wait time it seems to resolve itself and continues
>> > to work as expected.  After it finishes, checking the lock table again
>> > (using select * from syscs_diag.lock_table) there are only GRANT locks
>> > (however, checking the table before the problem there are no entries
>> > in the table).
>> >
>> > gory details:
>> >
>> > I have an application where I parse a number of files in a folder and
>> > put the contents into a database.  As time goes on new files may be
>> > added to this folder, and some time later I rescan the folder and
>> > reenter the data (relying on uniqueness constraints to avoid duplicate
>> > data).  If I get a uniqueness exception I do an update on the row that
>> > was already in the database.  Here's what's happening ...
>> >
>> > If my folder initially has 10 files all of the data goes in fine.
>> > Some time later, my folder might have 20 files, and it is rescanned.
>> > The first 9 files are rescanned and then updated when there's a
>> > duplicate without problem.  Then, the 10th file blocks on this lock, a
>> > minute later I get the exception, and then the remaining 10 files are
>> > successfully entered into the database.
>> >
>> > If I instead had 5 files initially and 10 files later, it would
>> > instead block on rescanning the 5th file.  It *always* blocks on the
>> > *last* previously scanned file.  All previously scanned files are
>> > updated without a problem, and all unscanned files are then
>> > successfully scanned.
>> >
>> > However, after the initial scan the lock table is empty ... there are
>> > no lingering locks whatsoever.
>> >
>> > The failed insert and subsequent update (attempt) are using the same
>> > connection.  Auto commit is set to true.
>> >
>> > Any ideas?
>> >
>> > Thanks-
>> > Robert
>> >
>> >
>> >
>
>

[Knut Anders Hatlen]

"Robert J. Carr" <rjcarr@...> writes:

> Hi Jeff-
>
> It initially happened in 10.3.2.1, but I just updated to 10.5.1.1 and
> the same problem exists.
>
> And I may have mentioned in the original post it was a table lock, and
> I don't know if I misread it initially or if something changed when I
> updated derby, but it seems to be a row lock.  Here's a condensed
> version of the lock trace:
>
> java.sql.SQLException: A lock could not be obtained within the time
> requested.  The lockTable dump is:
> XID       |TYPE   |MODE |LOCKCOUNT |LOCKNAME   |STATE |TABLENAME
> ----------------------------------------------------------------
> *** The following row is the victim ***
> 5222      |ROW    |X    |0         |(2,38)     |WAIT  |SG_TRACKS
> *** The above row is the victim ***
> 5104      |ROW    |S    |1         |(2,38)     |GRANT |SG_TRACKS
> 5104      |TABLE  |IS   |1         |Tablelock  |GRANT |SG_TRACKS
> 5222      |TABLE  |IX   |2         |Tablelock  |GRANT |SG_TRACKS
> ----------------------------------------------------------------

If you run with derby.language.logStatementText=true you'll be able to
find in derby.log which statements a transaction with a particular XID
has executed. This may help you track down the runaway transaction
that's holding onto the shared row lock.

--
Knut Anders

[rjcarr]

Thanks Knut ... that's the exact sort of thing I was looking for.
I'll test it next week and post a follow-up then.

On Sat, Jul 4, 2009 at 12:04 PM, Knut Anders Hatlen<Knut.Hatlen@...> wrote:

> "Robert J. Carr" <rjcarr@...> writes:
>
>> Hi Jeff-
>>
>> It initially happened in 10.3.2.1, but I just updated to 10.5.1.1 and
>> the same problem exists.
>>
>> And I may have mentioned in the original post it was a table lock, and
>> I don't know if I misread it initially or if something changed when I
>> updated derby, but it seems to be a row lock.  Here's a condensed
>> version of the lock trace:
>>
>> java.sql.SQLException: A lock could not be obtained within the time
>> requested.  The lockTable dump is:
>> XID       |TYPE   |MODE |LOCKCOUNT |LOCKNAME   |STATE |TABLENAME
>> ----------------------------------------------------------------
>> *** The following row is the victim ***
>> 5222      |ROW    |X    |0         |(2,38)     |WAIT  |SG_TRACKS
>> *** The above row is the victim ***
>> 5104      |ROW    |S    |1         |(2,38)     |GRANT |SG_TRACKS
>> 5104      |TABLE  |IS   |1         |Tablelock  |GRANT |SG_TRACKS
>> 5222      |TABLE  |IX   |2         |Tablelock  |GRANT |SG_TRACKS
>> ----------------------------------------------------------------
>
> If you run with derby.language.logStatementText=true you'll be able to
> find in derby.log which statements a transaction with a particular XID
> has executed. This may help you track down the runaway transaction
> that's holding onto the shared row lock.
>
> --
> Knut Anders
>

[rjcarr]

Hi Knut-

I've returned from a short holiday and hoping you could help me out a
bit more.  I think the flag you suggested is what I'm looking for, but
I don't know where to track down the logs.  I create my database using
ant and then later use it in tomcat.  When I create the database a
'derby.log' file is written into the same folder as my build.xml.
Here are the contents of that file:

----

2009-07-08 23:30:54.701 GMT:
 Booting Derby version The Apache Software Foundation - Apache Derby -
10.5.1.1 - (764942): instance a816c00e-0122-5cb4-9604-0000000f49d8
on database directory /Users/rjcarr/...

Database Class Loader started - derby.database.classpath=''

----

However, after it is created, nothing is added to it.  So I'm not sure
where to look to find these logs.  This link:

http://publib.boulder.ibm.com/infocenter/cscv/v10r1/index.jsp?topic=/com.ibm.cloudscape.doc/rtunproper43517.html

Says it is written to the "information log", but I don't know what that is.

When I added this flag:

derby.locks.deadlockTrace=true

The logTable dump (which I've posted earlier) is embedded into the
stack trace.  Looking at the stack trace after adding the flag you've
suggested I don't see anything different.

So, long story short, where do I find these log entries?

Thanks-
Robert

On Sat, Jul 4, 2009 at 12:04 PM, Knut Anders Hatlen<Knut.Hatlen@...> wrote:

> "Robert J. Carr" <rjcarr@...> writes:
>
>> Hi Jeff-
>>
>> It initially happened in 10.3.2.1, but I just updated to 10.5.1.1 and
>> the same problem exists.
>>
>> And I may have mentioned in the original post it was a table lock, and
>> I don't know if I misread it initially or if something changed when I
>> updated derby, but it seems to be a row lock.  Here's a condensed
>> version of the lock trace:
>>
>> java.sql.SQLException: A lock could not be obtained within the time
>> requested.  The lockTable dump is:
>> XID       |TYPE   |MODE |LOCKCOUNT |LOCKNAME   |STATE |TABLENAME
>> ----------------------------------------------------------------
>> *** The following row is the victim ***
>> 5222      |ROW    |X    |0         |(2,38)     |WAIT  |SG_TRACKS
>> *** The above row is the victim ***
>> 5104      |ROW    |S    |1         |(2,38)     |GRANT |SG_TRACKS
>> 5104      |TABLE  |IS   |1         |Tablelock  |GRANT |SG_TRACKS
>> 5222      |TABLE  |IX   |2         |Tablelock  |GRANT |SG_TRACKS
>> ----------------------------------------------------------------
>
> If you run with derby.language.logStatementText=true you'll be able to
> find in derby.log which statements a transaction with a particular XID
> has executed. This may help you track down the runaway transaction
> that's holding onto the shared row lock.
>
> --
> Knut Anders
>

[Knut Anders Hatlen]

"Robert J. Carr" <rjcarr@...> writes:

> Hi Knut-
>
> I've returned from a short holiday and hoping you could help me out a
> bit more.  I think the flag you suggested is what I'm looking for, but
> I don't know where to track down the logs.  I create my database using
> ant and then later use it in tomcat.  When I create the database a
> 'derby.log' file is written into the same folder as my build.xml.
> Here are the contents of that file:
>
> ----
>
> 2009-07-08 23:30:54.701 GMT:
>  Booting Derby version The Apache Software Foundation - Apache Derby -
> 10.5.1.1 - (764942): instance a816c00e-0122-5cb4-9604-0000000f49d8
> on database directory /Users/rjcarr/...
>
> Database Class Loader started - derby.database.classpath=''
>
> ----
>
> However, after it is created, nothing is added to it.  So I'm not sure
> where to look to find these logs.  This link:
>
> http://publib.boulder.ibm.com/infocenter/cscv/v10r1/index.jsp?topic=/com.ibm.cloudscape.doc/rtunproper43517.html
>
> Says it is written to the "information log", but I don't know what that is.
>
> When I added this flag:
>
> derby.locks.deadlockTrace=true
>
> The logTable dump (which I've posted earlier) is embedded into the
> stack trace.  Looking at the stack trace after adding the flag you've
> suggested I don't see anything different.
>
> So, long story short, where do I find these log entries?

Hi Robert,

Sorry for the late reply.

derby.log is where you should find these entries. How did you set the
property? One difference between derby.locks.deadlockTrace and
derby.language.logStatementText is that the former is dynamic and the
latter is static, meaning that if you set d.l.logStatementText with
SYSCS_UTIL.SYSCS_SET_DATABASE_PROPERTY, it won't take effect until you
have rebooted the database.

Does it work if you create a file called "derby.properties" in the same
directory as where you found derby.log and add the lines below to it?

derby.language.logStatementText=true
derby.locks.deadlockTrace=true

Then, after creating/using the database, derby.log should contain
entries similar to this one for each statement you have executed:

2009-07-17 10:05:26.608 GMT Thread[main,5,main] (XID = 144), (SESSIONID = 0), (DATABASE = db), (DRDAID = null), Begin compiling prepared statement: create table t(x int) :End prepared statement
2009-07-17 10:05:26.703 GMT Thread[main,5,main] (XID = 144), (SESSIONID = 0), (DATABASE = db), (DRDAID = null), End compiling prepared statement: create table t(x int) :End prepared statement
2009-07-17 10:05:26.716 GMT Thread[main,5,main] (XID = 144), (SESSIONID = 0), (DATABASE = db), (DRDAID = null), Executing prepared statement: create table t(x int) :End prepared statement

--
Knut Anders

[rjcarr]

Hi Knut-

It looks like things are being written to derby.log, but just not the
derby.log I was familiar with.  There's another derby.log file written
into a tomcat directory that looks to have the information I'm looking
for.

I'm inspecting it now ... thanks for the guidance!

Robert

On Fri, Jul 17, 2009 at 3:09 AM, Knut Anders Hatlen<Knut.Hatlen@...> wrote:

> "Robert J. Carr" <rjcarr@...> writes:
>
>> Hi Knut-
>>
>> I've returned from a short holiday and hoping you could help me out a
>> bit more.  I think the flag you suggested is what I'm looking for, but
>> I don't know where to track down the logs.  I create my database using
>> ant and then later use it in tomcat.  When I create the database a
>> 'derby.log' file is written into the same folder as my build.xml.
>> Here are the contents of that file:
>>
>> ----
>>
>> 2009-07-08 23:30:54.701 GMT:
>>  Booting Derby version The Apache Software Foundation - Apache Derby -
>> 10.5.1.1 - (764942): instance a816c00e-0122-5cb4-9604-0000000f49d8
>> on database directory /Users/rjcarr/...
>>
>> Database Class Loader started - derby.database.classpath=''
>>
>> ----
>>
>> However, after it is created, nothing is added to it.  So I'm not sure
>> where to look to find these logs.  This link:
>>
>> http://publib.boulder.ibm.com/infocenter/cscv/v10r1/index.jsp?topic=/com.ibm.cloudscape.doc/rtunproper43517.html
>>
>> Says it is written to the "information log", but I don't know what that is.
>>
>> When I added this flag:
>>
>> derby.locks.deadlockTrace=true
>>
>> The logTable dump (which I've posted earlier) is embedded into the
>> stack trace.  Looking at the stack trace after adding the flag you've
>> suggested I don't see anything different.
>>
>> So, long story short, where do I find these log entries?
>
> Hi Robert,
>
> Sorry for the late reply.
>
> derby.log is where you should find these entries. How did you set the
> property? One difference between derby.locks.deadlockTrace and
> derby.language.logStatementText is that the former is dynamic and the
> latter is static, meaning that if you set d.l.logStatementText with
> SYSCS_UTIL.SYSCS_SET_DATABASE_PROPERTY, it won't take effect until you
> have rebooted the database.
>
> Does it work if you create a file called "derby.properties" in the same
> directory as where you found derby.log and add the lines below to it?
>
> derby.language.logStatementText=true
> derby.locks.deadlockTrace=true
>
> Then, after creating/using the database, derby.log should contain
> entries similar to this one for each statement you have executed:
>
> 2009-07-17 10:05:26.608 GMT Thread[main,5,main] (XID = 144), (SESSIONID = 0), (DATABASE = db), (DRDAID = null), Begin compiling prepared statement: create table t(x int) :End prepared statement
> 2009-07-17 10:05:26.703 GMT Thread[main,5,main] (XID = 144), (SESSIONID = 0), (DATABASE = db), (DRDAID = null), End compiling prepared statement: create table t(x int) :End prepared statement
> 2009-07-17 10:05:26.716 GMT Thread[main,5,main] (XID = 144), (SESSIONID = 0), (DATABASE = db), (DRDAID = null), Executing prepared statement: create table t(x int) :End prepared statement
>
> --
> Knut Anders
>

[rjcarr]

Hi Knut, et al.-

So now, with your help, I can see the exact statement that is failing,
with the exact parameters that are being passed into the prepared
statement.  However, this is only giving me the "where", but I need to
know the "how" and more importantly the "why".

Superficially, the statement parameters don't look any different than
any other time it is used.  Nor are there any logs around the failed
statement to give any clue as to what is going wrong.  The only
difference is there is a log that says "Cleanup action starting" and
then there's a subsequent log that says "Failed Statement is:" and
gives the failed statement.

Again, in the lock table dump, all I'm seeing is this:

*** The following row is the victim ***
9526      |ROW          |X   |0        |(2,43)  |WAIT |T |NULL  |SG_TRACKS
*** The above row is the victim ***

Maybe the (2,43) is a clue?  Does this have anything to do with the
row and column numbers?

My point is, I have a lot of logging information and stack traces, but
still nothing is telling me why this happened.  Can someone explain
how derby can even get into a WAIT ROW LOCK without involving
concurrency?  I'm beginning to think this *might* be a derby problem
(but I've learned to eat similar words many times :) ).

Thanks!

On Tue, Jul 21, 2009 at 1:19 PM, Robert J. Carr<rjcarr@...> wrote:

> Hi Knut-
>
> It looks like things are being written to derby.log, but just not the
> derby.log I was familiar with.  There's another derby.log file written
> into a tomcat directory that looks to have the information I'm looking
> for.
>
> I'm inspecting it now ... thanks for the guidance!
>
> Robert
>
> On Fri, Jul 17, 2009 at 3:09 AM, Knut Anders Hatlen<Knut.Hatlen@...> wrote:
>> "Robert J. Carr" <rjcarr@...> writes:
>>
>>> Hi Knut-
>>>
>>> I've returned from a short holiday and hoping you could help me out a
>>> bit more.  I think the flag you suggested is what I'm looking for, but
>>> I don't know where to track down the logs.  I create my database using
>>> ant and then later use it in tomcat.  When I create the database a
>>> 'derby.log' file is written into the same folder as my build.xml.
>>> Here are the contents of that file:
>>>
>>> ----
>>>
>>> 2009-07-08 23:30:54.701 GMT:
>>>  Booting Derby version The Apache Software Foundation - Apache Derby -
>>> 10.5.1.1 - (764942): instance a816c00e-0122-5cb4-9604-0000000f49d8
>>> on database directory /Users/rjcarr/...
>>>
>>> Database Class Loader started - derby.database.classpath=''
>>>
>>> ----
>>>
>>> However, after it is created, nothing is added to it.  So I'm not sure
>>> where to look to find these logs.  This link:
>>>
>>> http://publib.boulder.ibm.com/infocenter/cscv/v10r1/index.jsp?topic=/com.ibm.cloudscape.doc/rtunproper43517.html
>>>
>>> Says it is written to the "information log", but I don't know what that is.
>>>
>>> When I added this flag:
>>>
>>> derby.locks.deadlockTrace=true
>>>
>>> The logTable dump (which I've posted earlier) is embedded into the
>>> stack trace.  Looking at the stack trace after adding the flag you've
>>> suggested I don't see anything different.
>>>
>>> So, long story short, where do I find these log entries?
>>
>> Hi Robert,
>>
>> Sorry for the late reply.
>>
>> derby.log is where you should find these entries. How did you set the
>> property? One difference between derby.locks.deadlockTrace and
>> derby.language.logStatementText is that the former is dynamic and the
>> latter is static, meaning that if you set d.l.logStatementText with
>> SYSCS_UTIL.SYSCS_SET_DATABASE_PROPERTY, it won't take effect until you
>> have rebooted the database.
>>
>> Does it work if you create a file called "derby.properties" in the same
>> directory as where you found derby.log and add the lines below to it?
>>
>> derby.language.logStatementText=true
>> derby.locks.deadlockTrace=true
>>
>> Then, after creating/using the database, derby.log should contain
>> entries similar to this one for each statement you have executed:
>>
>> 2009-07-17 10:05:26.608 GMT Thread[main,5,main] (XID = 144), (SESSIONID = 0), (DATABASE = db), (DRDAID = null), Begin compiling prepared statement: create table t(x int) :End prepared statement
>> 2009-07-17 10:05:26.703 GMT Thread[main,5,main] (XID = 144), (SESSIONID = 0), (DATABASE = db), (DRDAID = null), End compiling prepared statement: create table t(x int) :End prepared statement
>> 2009-07-17 10:05:26.716 GMT Thread[main,5,main] (XID = 144), (SESSIONID = 0), (DATABASE = db), (DRDAID = null), Executing prepared statement: create table t(x int) :End prepared statement
>>
>> --
>> Knut Anders
>>
>

[Knut Anders Hatlen]

"Robert J. Carr" <rjcarr@...> writes:

> Hi Knut, et al.-
>
> So now, with your help, I can see the exact statement that is failing,
> with the exact parameters that are being passed into the prepared
> statement.  However, this is only giving me the "where", but I need to
> know the "how" and more importantly the "why".
>
> Superficially, the statement parameters don't look any different than
> any other time it is used.  Nor are there any logs around the failed
> statement to give any clue as to what is going wrong.  The only
> difference is there is a log that says "Cleanup action starting" and
> then there's a subsequent log that says "Failed Statement is:" and
> gives the failed statement.
>
> Again, in the lock table dump, all I'm seeing is this:
>
> *** The following row is the victim ***
> 9526      |ROW          |X   |0        |(2,43)  |WAIT |T |NULL  |SG_TRACKS
> *** The above row is the victim ***
>
> Maybe the (2,43) is a clue?  Does this have anything to do with the
> row and column numbers?

Yes, (2,43) tells you the page number (2) and the row number (43) within
that page. So what you should be looking for in the lock table dump is
other occurrences of row locks on (2,43) in the SG_TRACKS table. Then
look in derby.log for statements with the same transaction id as those
occurrences. This should give you a clue as to where in your code the
locks are held.

> My point is, I have a lot of logging information and stack traces, but
> still nothing is telling me why this happened.  Can someone explain
> how derby can even get into a WAIT ROW LOCK without involving
> concurrency?

That's simple. :) Just don't commit your transactions:

Connection c1 = DriverManager.getConnection("jdbc:derby:db");
c1.setAutoCommit(false);
c1.createStatement().execute("update t set x = x + 1");
Connection c2 = DriverManager.getConnection("jdbc:derby:db");
c2.createStatement().execute("update t set x = x - 1"); // will time out

--
Knut Anders

[rjcarr]

Hi Knut-

Thanks for the quick reply, and sorry to burden everyone, but I have a
quick follow-up:

> Yes, (2,43) tells you the page number (2) and the row number (43)

Could you explain what the page number represents?

> That's simple. :) Just don't commit your transactions:

I did have a handful of setAutoCommit() methods but I removed all
traces of them and I get the same problem in the same exact way.  I
also logged the auto commit status and before the problem occurs it is
set to TRUE.  Can you think of anything else that may cause a lock in
this way?

Thanks!

On Tue, Jul 21, 2009 at 2:34 PM, Knut Anders Hatlen<Knut.Hatlen@...> wrote:

> "Robert J. Carr" <rjcarr@...> writes:
>
>> Hi Knut, et al.-
>>
>> So now, with your help, I can see the exact statement that is failing,
>> with the exact parameters that are being passed into the prepared
>> statement.  However, this is only giving me the "where", but I need to
>> know the "how" and more importantly the "why".
>>
>> Superficially, the statement parameters don't look any different than
>> any other time it is used.  Nor are there any logs around the failed
>> statement to give any clue as to what is going wrong.  The only
>> difference is there is a log that says "Cleanup action starting" and
>> then there's a subsequent log that says "Failed Statement is:" and
>> gives the failed statement.
>>
>> Again, in the lock table dump, all I'm seeing is this:
>>
>> *** The following row is the victim ***
>> 9526      |ROW          |X   |0        |(2,43)  |WAIT |T |NULL  |SG_TRACKS
>> *** The above row is the victim ***
>>
>> Maybe the (2,43) is a clue?  Does this have anything to do with the
>> row and column numbers?
>
> Yes, (2,43) tells you the page number (2) and the row number (43) within
> that page. So what you should be looking for in the lock table dump is
> other occurrences of row locks on (2,43) in the SG_TRACKS table. Then
> look in derby.log for statements with the same transaction id as those
> occurrences. This should give you a clue as to where in your code the
> locks are held.
>
>> My point is, I have a lot of logging information and stack traces, but
>> still nothing is telling me why this happened.  Can someone explain
>> how derby can even get into a WAIT ROW LOCK without involving
>> concurrency?
>
> That's simple. :) Just don't commit your transactions:
>
> Connection c1 = DriverManager.getConnection("jdbc:derby:db");
> c1.setAutoCommit(false);
> c1.createStatement().execute("update t set x = x + 1");
> Connection c2 = DriverManager.getConnection("jdbc:derby:db");
> c2.createStatement().execute("update t set x = x - 1"); // will time out
>
> --
> Knut Anders
>

[Knut Anders Hatlen]

"Robert J. Carr" <rjcarr@...> writes:

> Hi Knut-
>
> Thanks for the quick reply, and sorry to burden everyone, but I have a
> quick follow-up:
>
>> Yes, (2,43) tells you the page number (2) and the row number (43)
>
> Could you explain what the page number represents?

A table is stored in a file (aka conglomerate) which is divided into
pages, where each page usually is 4 KB. So the page number tells you in
which section of the file you will find the row, and the pair (page
number, row number) uniquely identifies the row within the file.

>> That's simple. :) Just don't commit your transactions:
>
> I did have a handful of setAutoCommit() methods but I removed all
> traces of them and I get the same problem in the same exact way.  I
> also logged the auto commit status and before the problem occurs it is
> set to TRUE.  Can you think of anything else that may cause a lock in
> this way?

If you retrieve a ResultSet, the transaction isn't auto-committed until
the ResultSet is closed, so leaving one open could cause locks to be
held.

--
Knut Anders

[rjcarr]

Hi Knut-

Just writing to say ...

> If you retrieve a ResultSet, the transaction isn't auto-committed until
> the ResultSet is closed, so leaving one open could cause locks to be
> held.

BINGO!!!  That was it ... a result set wasn't being closed and it was
causing the lock.  Thank you so much for helping to track this down!

Regards-
Robert