Derby
  1. Derby
  2. DERBY-5454

ERROR 40001 deadlock in nstest on select max(serialkey)

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.7.1.1, 10.8.2.2
    • Fix Version/s: 10.8.3.0, 10.9.1.0
    • Component/s: Test
    • Labels:
      None
    • Bug behavior facts:
      Regression Test Failure

      Description

      nstest with 10.8.2 (both 10.8.2.1 RC2 (revision 1170221) and builds off the 10.8. tree at 10.8.2.2 level after backing out re DERBY-5448) show deadlock errors like the following:

      Caused by: ERROR 40001: A lock could not be obtained due to a deadlock, cycle of
      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.EmbedResultSet.closeOnTransactionError(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedResultSet.next(Unknown Source)
      at org.apache.derbyTesting.system.nstest.utils.DbUtil.pick_one(DbUtil.java:491)
      at org.apache.derbyTesting.system.nstest.utils.DbUtil.delete_one_row(DbUtil.java:418)
      at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:175)
      at org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:109)
      at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:555)
      Caused by: java.sql.SQLException: A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
      Lock : ROW, NSTESTTAB, (619,15)
      Waiting XID :

      {104564, S}

      , NSTEST, select max(serialkey) from nstesttab where serialkey > ?
      Granted XID :

      {104179, X}

      Lock : ROW, NSTESTTAB, (619,16)
      Waiting XID :

      {104179, S}

      , NSTEST, select max(serialkey) from nstesttab where serialkey > ?
      Granted XID :

      {104564, X}

      . The selected victim is XID : 104564.
      at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
      at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown Source)
      ... 14 more

      For more examples, see comments on DERBY-5448.

      1. DERBY-5454_try2.diff
        3 kB
        Myrna van Lunteren
      2. DERBY-5454_try1.diff
        2 kB
        Myrna van Lunteren

        Issue Links

          Activity

          Myrna van Lunteren created issue -
          Myrna van Lunteren made changes -
          Field Original Value New Value
          Link This issue is related to DERBY-5448 [ DERBY-5448 ]
          Hide
          Myrna van Lunteren added a comment -

          It seems from comments in DERBY-5448, that the consensus is that this issue is most likely pre-dating 10.8.2.
          Thus, I'm not marking it blocker for 10.8.2.

          Show
          Myrna van Lunteren added a comment - It seems from comments in DERBY-5448 , that the consensus is that this issue is most likely pre-dating 10.8.2. Thus, I'm not marking it blocker for 10.8.2.
          Hide
          Knut Anders Hatlen added a comment -

          Seems like this deadlock predates 10.8.1 too. I started NsTest on 10.7.1.1 (embedded, default settings) and after just a few minutes I saw this deadlock trace:

          java.sql.SQLTransactionRollbackException: A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
          Lock : ROW, NSTESTTAB, (685,18)
          Waiting XID :

          {126705, S} , NSTEST, select max(serialkey) from nstesttab where serialkey > ?
          Granted XID : {126703, X}
          Lock : ROW, NSTESTTAB, (685,19)
          Waiting XID : {126703, S} , NSTEST, select max(serialkey) from nstesttab where serialkey > ?
          Granted XID : {126705, X}
          . The selected victim is XID : 126705. while selecting a random row
          java.sql.SQLTransactionRollbackException: A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
          Lock : ROW, NSTESTTAB, (685,18)
          Waiting XID : {126705, S}

          , NSTEST, select max(serialkey) from nstesttab where serialkey > ?
          Granted XID :

          {126703, X}


          Lock : ROW, NSTESTTAB, (685,19)
          Waiting XID :

          {126703, S}

          , NSTEST, select max(serialkey) from nstesttab where serialkey > ?
          Granted XID :

          {126705, X}


          . The selected victim is XID : 126705.
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.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.EmbedResultSet.closeOnTransactionError(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedResultSet.next(Unknown Source)
          at org.apache.derbyTesting.system.nstest.utils.DbUtil.pick_one(DbUtil.java:527)
          at org.apache.derbyTesting.system.nstest.utils.DbUtil.delete_one_row(DbUtil.java:440)
          at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:175)
          at org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:109)
          at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:555)

          Show
          Knut Anders Hatlen added a comment - Seems like this deadlock predates 10.8.1 too. I started NsTest on 10.7.1.1 (embedded, default settings) and after just a few minutes I saw this deadlock trace: java.sql.SQLTransactionRollbackException: A lock could not be obtained due to a deadlock, cycle of locks and waiters is: Lock : ROW, NSTESTTAB, (685,18) Waiting XID : {126705, S} , NSTEST, select max(serialkey) from nstesttab where serialkey > ? Granted XID : {126703, X} Lock : ROW, NSTESTTAB, (685,19) Waiting XID : {126703, S} , NSTEST, select max(serialkey) from nstesttab where serialkey > ? Granted XID : {126705, X} . The selected victim is XID : 126705. while selecting a random row java.sql.SQLTransactionRollbackException: A lock could not be obtained due to a deadlock, cycle of locks and waiters is: Lock : ROW, NSTESTTAB, (685,18) Waiting XID : {126705, S} , NSTEST, select max(serialkey) from nstesttab where serialkey > ? Granted XID : {126703, X} Lock : ROW, NSTESTTAB, (685,19) Waiting XID : {126703, S} , NSTEST, select max(serialkey) from nstesttab where serialkey > ? Granted XID : {126705, X} . The selected victim is XID : 126705. at org.apache.derby.impl.jdbc.SQLExceptionFactory40.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.EmbedResultSet.closeOnTransactionError(Unknown Source) at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(Unknown Source) at org.apache.derby.impl.jdbc.EmbedResultSet.next(Unknown Source) at org.apache.derbyTesting.system.nstest.utils.DbUtil.pick_one(DbUtil.java:527) at org.apache.derbyTesting.system.nstest.utils.DbUtil.delete_one_row(DbUtil.java:440) at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:175) at org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:109) at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:555)
          Knut Anders Hatlen made changes -
          Affects Version/s 10.7.1.1 [ 12315564 ]
          Knut Anders Hatlen made changes -
          Link This issue is related to DERBY-5430 [ DERBY-5430 ]
          Myrna van Lunteren made changes -
          Affects Version/s 10.8.2.1 [ 12317957 ]
          Mike Matrigali made changes -
          Component/s Test [ 11413 ]
          Kathey Marsden made changes -
          Link This issue relates to DERBY-5671 [ DERBY-5671 ]
          Hide
          Myrna van Lunteren added a comment -

          I'm attaching an attempt to work around this deadlock issue by not doing the select max(serial_key) at all, and instead obtaining a random number without using jdbc.

          It seems to work in as far as that with this change I do not see the deadlock on max(serial_key) (of course, not as the code's no longer there), but unfortunately I also see some ERROR 23505s popping up:

          ------from the test output redirected to nstest.out: -----------
          Tester2Thread 4 inserted 1 row with id -764407904
          Exception when preparing or executing insert prepared stmt
          java.sql.SQLIntegrityConstraintViolationException: The statement was aborted because it would have caused a duplicate key value in a unique or primary key constraint or unique index identified by 'SQL120322210301700' defined on 'NSTESTTAB'.
          Tester2Thread 4 dbUtil ----> During executing/preparing insert stmt in dbUtil, exception thrown was : java.sql.SQLIntegrityConstraintViolationException: The statement was aborted because it would have caused a duplicate key value in a unique or primary key constraint or unique index identified by 'SQL120322210301700' defined on 'NSTESTTAB'.
          java.sql.SQLIntegrityConstraintViolationException: The statement was aborted because it would have caused a duplicate key value in a unique or primary key constraint or unique index identified by 'SQL120322210301700' defined on 'NSTESTTAB'.
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:82)
          at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Util.java:256)
          at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:424)
          at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:353)
          at org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2360)
          at org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:82)
          at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1334)
          at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(EmbedPreparedStatement.java:1715)
          at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeUpdate(EmbedPreparedStatement.java:311)
          at org.apache.derbyTesting.system.nstest.utils.DbUtil.add_one_row(DbUtil.java:197)
          at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:148)
          at org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:109)
          at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:555)
          Caused by: java.sql.SQLException: The statement was aborted because it would have caused a duplicate key value in a unique or primary key constraint or unique index identified by 'SQL120322210301700' defined on 'NSTESTTAB'.
          at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:42)
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:122)
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:71)
          ... 12 more
          Caused by: ERROR 23505: The statement was aborted because it would have caused a duplicate key value in a unique or primary key constraint or unique index identified by 'SQL120322210301700' defined on 'NSTESTTAB'.
          at org.apache.derby.iapi.error.StandardException.newException(StandardException.java:295)
          at org.apache.derby.impl.sql.execute.IndexChanger.insertAndCheckDups(IndexChanger.java:466)
          at org.apache.derby.impl.sql.execute.IndexChanger.doInsert(IndexChanger.java:383)
          at org.apache.derby.impl.sql.execute.IndexChanger.insert(IndexChanger.java:590)
          at org.apache.derby.impl.sql.execute.IndexSetChanger.insert(IndexSetChanger.java:268)
          at org.apache.derby.impl.sql.execute.RowChangerImpl.insertRow(RowChangerImpl.java:453)
          at org.apache.derby.impl.sql.execute.InsertResultSet.normalInsertCore(InsertResultSet.java:999)
          at org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:519)
          at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(GenericPreparedStatement.java:443)
          at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:324)
          at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1242)
          ... 6 more

          ----------------------------------------------------------------

          So I don't think this is quite right. I'll look at it some more.

          I also wondered if perhaps it would be useful to have a test that has a good chance of hitting deadlock issues and perhaps I should make the old code available with a special test property...But decided against that because the deadlock was not happening all the time.

          Show
          Myrna van Lunteren added a comment - I'm attaching an attempt to work around this deadlock issue by not doing the select max(serial_key) at all, and instead obtaining a random number without using jdbc. It seems to work in as far as that with this change I do not see the deadlock on max(serial_key) (of course, not as the code's no longer there), but unfortunately I also see some ERROR 23505s popping up: ------from the test output redirected to nstest.out: ----------- Tester2Thread 4 inserted 1 row with id -764407904 Exception when preparing or executing insert prepared stmt java.sql.SQLIntegrityConstraintViolationException: The statement was aborted because it would have caused a duplicate key value in a unique or primary key constraint or unique index identified by 'SQL120322210301700' defined on 'NSTESTTAB'. Tester2Thread 4 dbUtil ----> During executing/preparing insert stmt in dbUtil, exception thrown was : java.sql.SQLIntegrityConstraintViolationException: The statement was aborted because it would have caused a duplicate key value in a unique or primary key constraint or unique index identified by 'SQL120322210301700' defined on 'NSTESTTAB'. java.sql.SQLIntegrityConstraintViolationException: The statement was aborted because it would have caused a duplicate key value in a unique or primary key constraint or unique index identified by 'SQL120322210301700' defined on 'NSTESTTAB'. at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:82) at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Util.java:256) at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:424) at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:353) at org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2360) at org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:82) at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1334) at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(EmbedPreparedStatement.java:1715) at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeUpdate(EmbedPreparedStatement.java:311) at org.apache.derbyTesting.system.nstest.utils.DbUtil.add_one_row(DbUtil.java:197) at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:148) at org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:109) at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:555) Caused by: java.sql.SQLException: The statement was aborted because it would have caused a duplicate key value in a unique or primary key constraint or unique index identified by 'SQL120322210301700' defined on 'NSTESTTAB'. at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:42) at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:122) at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:71) ... 12 more Caused by: ERROR 23505: The statement was aborted because it would have caused a duplicate key value in a unique or primary key constraint or unique index identified by 'SQL120322210301700' defined on 'NSTESTTAB'. at org.apache.derby.iapi.error.StandardException.newException(StandardException.java:295) at org.apache.derby.impl.sql.execute.IndexChanger.insertAndCheckDups(IndexChanger.java:466) at org.apache.derby.impl.sql.execute.IndexChanger.doInsert(IndexChanger.java:383) at org.apache.derby.impl.sql.execute.IndexChanger.insert(IndexChanger.java:590) at org.apache.derby.impl.sql.execute.IndexSetChanger.insert(IndexSetChanger.java:268) at org.apache.derby.impl.sql.execute.RowChangerImpl.insertRow(RowChangerImpl.java:453) at org.apache.derby.impl.sql.execute.InsertResultSet.normalInsertCore(InsertResultSet.java:999) at org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:519) at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(GenericPreparedStatement.java:443) at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:324) at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1242) ... 6 more ---------------------------------------------------------------- So I don't think this is quite right. I'll look at it some more. I also wondered if perhaps it would be useful to have a test that has a good chance of hitting deadlock issues and perhaps I should make the old code available with a special test property...But decided against that because the deadlock was not happening all the time.
          Myrna van Lunteren made changes -
          Attachment DERBY-5454_try1.diff [ 12520041 ]
          Hide
          Myrna van Lunteren added a comment -

          Attaching a second patch which just does not attempt to do a select max(serial_key).
          I found the original code confusing and the comments appeared contrary to what was happening.
          A deadlock was happening regularly but seemed not the point, and so was only complicating the test.

          I modified the code to just generate a random number and insert that.
          If no one has any objections I'll commit this over the weekend and backport it to 10.8.

          Show
          Myrna van Lunteren added a comment - Attaching a second patch which just does not attempt to do a select max(serial_key). I found the original code confusing and the comments appeared contrary to what was happening. A deadlock was happening regularly but seemed not the point, and so was only complicating the test. I modified the code to just generate a random number and insert that. If no one has any objections I'll commit this over the weekend and backport it to 10.8.
          Myrna van Lunteren made changes -
          Attachment DERBY-5454_try2.diff [ 12521783 ]
          Hide
          Myrna van Lunteren added a comment -

          I committed the change to remove the 'select max(serialkey) where...' code to trunk with revision 1311804 and merged it to 10.8 with revision 1311975.

          Closing this issue.

          Show
          Myrna van Lunteren added a comment - I committed the change to remove the 'select max(serialkey) where...' code to trunk with revision 1311804 and merged it to 10.8 with revision 1311975. Closing this issue.
          Myrna van Lunteren made changes -
          Status Open [ 1 ] Closed [ 6 ]
          Assignee Myrna van Lunteren [ myrna ]
          Fix Version/s 10.8.2.3 [ 12318540 ]
          Fix Version/s 10.9.0.0 [ 12316344 ]
          Resolution Fixed [ 1 ]
          Kathey Marsden made changes -
          Fix Version/s 10.8.3.0 [ 12323456 ]
          Fix Version/s 10.8.2.3 [ 12318540 ]
          Gavin made changes -
          Workflow jira [ 12637108 ] Default workflow, editable Closed status [ 12802123 ]

            People

            • Assignee:
              Myrna van Lunteren
              Reporter:
              Myrna van Lunteren
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development