Derby
  1. Derby
  2. DERBY-5667

testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Won't Fix
    • Affects Version/s: 10.8.3.0
    • Fix Version/s: 10.8.3.0, 10.9.1.0
    • Component/s: Test
    • Labels:
      None
    • Issue & fix info:
      Patch Available
    • Bug behavior facts:
      Regression Test Failure

      Description

      one failure and 2 errors which I would guess are because of the failure. Failed against 10.8 branch, ibm15, windows, build 1302046
      There were 2 errors:
      1) testSerializable(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)java.sql.SQLException: Table/View 'A' already exists in Schema 'APP'.
      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.EmbedStatement.execute(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedStatement.executeUpdate(Unknown Source)
      at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:185)
      at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testSerializable(UpdateLocksTest.java:154)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:79)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
      at junit.extensions.TestSetup.run(TestSetup.java:25)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
      at junit.extensions.TestSetup.run(TestSetup.java:25)
      at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
      Caused by: ERROR X0Y32: Table/View 'A' already exists in Schema 'APP'.
      at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.duplicateDescriptorException(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.addDescriptor(Unknown Source)
      at org.apache.derby.impl.sql.execute.CreateTableConstantAction.executeConstantAction(Unknown Source)
      at org.apache.derby.impl.sql.execute.MiscResultSet.open(Unknown Source)
      at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(Unknown Source)
      at org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown Source)
      ... 36 more
      2) testReadUncommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)java.sql.SQLException: Table/View 'A' already exists in Schema 'APP'.
      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.EmbedStatement.execute(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedStatement.executeUpdate(Unknown Source)
      at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:185)
      at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testReadUncommitted(UpdateLocksTest.java:158)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:79)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
      at junit.extensions.TestSetup.run(TestSetup.java:25)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
      at junit.extensions.TestSetup.run(TestSetup.java:25)
      at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
      Caused by: ERROR X0Y32: Table/View 'A' already exists in Schema 'APP'.
      at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.duplicateDescriptorException(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.addDescriptor(Unknown Source)
      at org.apache.derby.impl.sql.execute.CreateTableConstantAction.executeConstantAction(Unknown Source)
      at org.apache.derby.impl.sql.execute.MiscResultSet.open(Unknown Source)
      at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(Unknown Source)
      at org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown Source)
      ... 36 more
      There were 2 failures:
      1) testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet
      at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java:1349)
      at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java:1285)
      at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeSetLocks(UpdateLocksTest.java:6764)
      at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:387)
      at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testReadCommitted(UpdateLocksTest.java:150)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:79)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
      at junit.extensions.TestSetup.run(TestSetup.java:25)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
      at junit.extensions.TestSetup.run(TestSetup.java:25)
      at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)

      http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm15/1302046-suites.All_diff.txt

      1. DERBY-5667_2.diff
        7 kB
        Myrna van Lunteren
      2. DERBY-5667_3_109.diff
        4 kB
        Myrna van Lunteren
      3. DERBY-5667_3.diff
        4 kB
        Myrna van Lunteren
      4. DERBY-5667_3b.diff
        4 kB
        Myrna van Lunteren
      5. DERBY-5667.diff
        2 kB
        Myrna van Lunteren

        Activity

        Hide
        Myrna van Lunteren added a comment -

        I see this failure pop up frequently in the nightly tests.

        I did a cursory check, a variation of this has been happening before Mike logged it, see e.g. the run on Fri Mar 9, 2012 on this same platform (10.8 on windows 2008 / ibm 1.7):
        testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Unexpected row count expected:<2> but was:<3>
        (http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm17/1299147-suites.All_diff.txt)

        The current failure is happening a couple of times per week.
        For example

        Just like the intermittent AccessTest failure of DERBY-5377 this problem seems to show up only on this machine, but not reproducible at will or with a smaller subset of tests than suites.All even on this machine.
        I do not have another Windows 2008 machine available to check if it's something related to this OS.
        I also do not have any other 4 CPU boxes available to me to do further experimenting with that.

        Show
        Myrna van Lunteren added a comment - I see this failure pop up frequently in the nightly tests. I did a cursory check, a variation of this has been happening before Mike logged it, see e.g. the run on Fri Mar 9, 2012 on this same platform (10.8 on windows 2008 / ibm 1.7): testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Unexpected row count expected:<2> but was:<3> ( http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm17/1299147-suites.All_diff.txt ) The current failure is happening a couple of times per week. For example Fri April 5, 2012, ibm 1.7 on windows 2008: http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm17/1310152-suites.All_diff.txt Mon April 9, 2012, ibm 1.7 on windows 2008: http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm17/1311551-suites.All_diff.txt Tue April 10, 2012, ibm 1.4.2 on windows 2008: http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm142/1312069-suites.All_diff.txt Just like the intermittent AccessTest failure of DERBY-5377 this problem seems to show up only on this machine, but not reproducible at will or with a smaller subset of tests than suites.All even on this machine. I do not have another Windows 2008 machine available to check if it's something related to this OS. I also do not have any other 4 CPU boxes available to me to do further experimenting with that.
        Hide
        Myrna van Lunteren added a comment -

        Attaching a patch that creates a WAIT_FOR_POST_COMMIT procedure in the decorateSQL and then calls it before doing the assertUnorderedResultSet after a delete.

        I intend to commit this shortly; then backport it to 10.8.

        As I've not been able to reproduce the issue at will this is a bit of a guess, we might have to revisit the issue again later.

        Show
        Myrna van Lunteren added a comment - Attaching a patch that creates a WAIT_FOR_POST_COMMIT procedure in the decorateSQL and then calls it before doing the assertUnorderedResultSet after a delete. I intend to commit this shortly; then backport it to 10.8. As I've not been able to reproduce the issue at will this is a bit of a guess, we might have to revisit the issue again later.
        Hide
        Mike Matrigali added a comment -

        comments from the review. The call to wait_for_post_commit should be placed after the commit that follows a delete. putting after the delete but before the commit does not help. The problem is caused by async work done that starts when commit is called.

        The calls on lines 6774 and 7140 and 7340 are all too soon, they should come after the first commit following the delete.

        Also the change does not handle the deletes that are made because of deleteRow() being called.

        Show
        Mike Matrigali added a comment - comments from the review. The call to wait_for_post_commit should be placed after the commit that follows a delete. putting after the delete but before the commit does not help. The problem is caused by async work done that starts when commit is called. The calls on lines 6774 and 7140 and 7340 are all too soon, they should come after the first commit following the delete. Also the change does not handle the deletes that are made because of deleteRow() being called.
        Hide
        Myrna van Lunteren added a comment - - edited

        You're right of course.
        This was because I looked at the stack trace of the original error, which shows this:
        ------------
        testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet
        at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java:1349)
        at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java:1285)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeSetLocks(UpdateLocksTest.java:6764)
        -------------
        So I assumed I had to put the call for wait_for_post_commit before the assertUnorderedResultSet call on line 6764.

        The delete-commit it would affect is then not the delete call right before ((original file line 6760/6761): s.executeUpdate("delete from a where a = 2 or a = 4 or a = 6")
        Because, as you say, there's no commit for that one yet.
        Instead it would be for the earlier delete (original file line 6689/6690):
        s.executeUpdate(
        "delete from a where a = 4");
        which got committed on line (again, original file numbers 6732.

        Still, there's no good explanation for the placing of the other wait_for_commit calls. I will make a new patch that does the call after the commit belonging to each delete - and after the commit following each deleteRow() call.

        Show
        Myrna van Lunteren added a comment - - edited You're right of course. This was because I looked at the stack trace of the original error, which shows this: ------------ testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java:1349) at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java:1285) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeSetLocks(UpdateLocksTest.java:6764) ------------- So I assumed I had to put the call for wait_for_post_commit before the assertUnorderedResultSet call on line 6764. The delete-commit it would affect is then not the delete call right before ((original file line 6760/6761): s.executeUpdate("delete from a where a = 2 or a = 4 or a = 6") Because, as you say, there's no commit for that one yet. Instead it would be for the earlier delete (original file line 6689/6690): s.executeUpdate( "delete from a where a = 4"); which got committed on line (again, original file numbers 6732. Still, there's no good explanation for the placing of the other wait_for_commit calls. I will make a new patch that does the call after the commit belonging to each delete - and after the commit following each deleteRow() call.
        Hide
        Myrna van Lunteren added a comment -

        Attaching patch _2.diff which puts the calls for wait_for_post_commit after each commit following a delete.

        Show
        Myrna van Lunteren added a comment - Attaching patch _2.diff which puts the calls for wait_for_post_commit after each commit following a delete.
        Hide
        Mike Matrigali added a comment -

        the second patch looks good to me.

        Show
        Mike Matrigali added a comment - the second patch looks good to me.
        Hide
        Myrna van Lunteren added a comment -

        I applied the changes as per patch _2.diff to trunk with revision 1330482 and merged 1330066 and 1330482 to 10.8 with revision 1330489.
        I'm resolving this issue. It's possible the test will fail again because of activity resulting from updates, if it does, we can repeat the solution for that.

        Show
        Myrna van Lunteren added a comment - I applied the changes as per patch _2.diff to trunk with revision 1330482 and merged 1330066 and 1330482 to 10.8 with revision 1330489. I'm resolving this issue. It's possible the test will fail again because of activity resulting from updates, if it does, we can repeat the solution for that.
        Hide
        Myrna van Lunteren added a comment -

        The problem occurred again last night, with ibm 1.4.2, with the 10.8 branch updated to revision 1346212.

        This is the stack trace:

        1) testReadUncommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet
        at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code))
        at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code))
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeSetLocks(UpdateLocksTest.java:7373)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:264)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testReadUncommitted(UpdateLocksTest.java:168)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Compiled Code))
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Compiled Code))
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java(Compiled Code))
        at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java(Compiled Code))
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)

        Show
        Myrna van Lunteren added a comment - The problem occurred again last night, with ibm 1.4.2, with the 10.8 branch updated to revision 1346212. This is the stack trace: 1) testReadUncommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code)) at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code)) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeSetLocks(UpdateLocksTest.java:7373) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:264) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testReadUncommitted(UpdateLocksTest.java:168) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Compiled Code)) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Compiled Code)) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java(Compiled Code)) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java(Compiled Code)) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        Show
        Myrna van Lunteren added a comment - See: http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm142/1346212-suites.All_diff.txt
        Hide
        Myrna van Lunteren added a comment -

        Looking again at the previous mention, it seems something else than post-commit activity after a delete-commit is going on, because the code that failed already had the post-commit call in place...
        I think more detailed output on error would help.

        This test failed again, on July 24, on nightly builds off the 10.8 branch synced to revision 1365402 on windows with ibm 1.4.2.:
        http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm142/1365402-suites.All_diff.txt.

        The stack trace indicates the trouble this time was after an update, not a delete:
        1) testSerializable(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Unexpected row count expected:<4> but was:<6>
        at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code))
        at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code))
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeSetLocks(UpdateLocksTest.java:7085)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:252)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testSerializable(UpdateLocksTest.java:164)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Compiled Code))
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Compiled Code))
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java(Compiled Code))
        at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java(Compiled Code))
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        (There was also an error in the subsequent fixture testReadUncommitted (java.sql.SQLException: Table/View 'A' already exists in Schema 'APP') - but I'm chalking that up to a result of the failure)

        Also, I it seems these failures in UpdateLocksTest seem to be happening only on the machine running 10.8 windows tests, and most often with ibm 1.4.2. Could be there's just more concurrency trouble on this machine - it's a 4 CPU but it's running suites.All for 6 jvm versions at the same time...

        I will work towards a new patch which does:
        1. print out more detailed info on error
        2. adds the wait_for_post_commit calls to all commits following an update.

        Show
        Myrna van Lunteren added a comment - Looking again at the previous mention, it seems something else than post-commit activity after a delete-commit is going on, because the code that failed already had the post-commit call in place... I think more detailed output on error would help. This test failed again, on July 24, on nightly builds off the 10.8 branch synced to revision 1365402 on windows with ibm 1.4.2.: http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm142/1365402-suites.All_diff.txt . The stack trace indicates the trouble this time was after an update, not a delete: 1) testSerializable(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Unexpected row count expected:<4> but was:<6> at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code)) at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code)) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeSetLocks(UpdateLocksTest.java:7085) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:252) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testSerializable(UpdateLocksTest.java:164) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Compiled Code)) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Compiled Code)) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java(Compiled Code)) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java(Compiled Code)) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) (There was also an error in the subsequent fixture testReadUncommitted (java.sql.SQLException: Table/View 'A' already exists in Schema 'APP') - but I'm chalking that up to a result of the failure) Also, I it seems these failures in UpdateLocksTest seem to be happening only on the machine running 10.8 windows tests, and most often with ibm 1.4.2. Could be there's just more concurrency trouble on this machine - it's a 4 CPU but it's running suites.All for 6 jvm versions at the same time... I will work towards a new patch which does: 1. print out more detailed info on error 2. adds the wait_for_post_commit calls to all commits following an update.
        Hide
        Myrna van Lunteren added a comment -

        Attaching a patch which:

        • in store.UpdateLocksTest, adds a call to wait_for_post_commit after each commit following an update
        • in junit.JDBC, modifies the 'missing Rows' output to always print out the actual and expected rows:

        Index: java/testing/org/apache/derbyTesting/junit/JDBC.java
        ===================================================================
        — java/testing/org/apache/derbyTesting/junit/JDBC.java (revision 1368744)
        +++ java/testing/org/apache/derbyTesting/junit/JDBC.java (working copy)
        @@ -1392,7 +1392,9 @@
        expected.removeAll( actual );
        BaseTestCase.println
        ( "These expected rows don't appear in the actual result: " + expected );

        • Assert.fail( "Missing rows in ResultSet" );
          + String message = "Missing rows in ResultSet; expected rows: \n\t"
          + + expected + ", actual result: \n\t" + actual;
          + Assert.fail( message );
          }
          }

        I hesitated before changing this, because there is a BaseTestCase.println line that does mostly the same - but of course we need to have verbose on. I could change the nightly run mechanisms to always run with verbose. But I think that will give us too much info in full runs, and this test does not fail often.

        Also, this change is on trunk, and I tend to backport to 10.8, as it is the community's common practice to backport from trunk. However. Alternatively, I could make this change only on 10.8, as that is where we appear to be seeing this (mostly?). Anyone having a preference to this 10.8 alternative?

        Show
        Myrna van Lunteren added a comment - Attaching a patch which: in store.UpdateLocksTest, adds a call to wait_for_post_commit after each commit following an update in junit.JDBC, modifies the 'missing Rows' output to always print out the actual and expected rows: Index: java/testing/org/apache/derbyTesting/junit/JDBC.java =================================================================== — java/testing/org/apache/derbyTesting/junit/JDBC.java (revision 1368744) +++ java/testing/org/apache/derbyTesting/junit/JDBC.java (working copy) @@ -1392,7 +1392,9 @@ expected.removeAll( actual ); BaseTestCase.println ( "These expected rows don't appear in the actual result: " + expected ); Assert.fail( "Missing rows in ResultSet" ); + String message = "Missing rows in ResultSet; expected rows: \n\t" + + expected + ", actual result: \n\t" + actual; + Assert.fail( message ); } } I hesitated before changing this, because there is a BaseTestCase.println line that does mostly the same - but of course we need to have verbose on. I could change the nightly run mechanisms to always run with verbose. But I think that will give us too much info in full runs, and this test does not fail often. Also, this change is on trunk, and I tend to backport to 10.8, as it is the community's common practice to backport from trunk. However. Alternatively, I could make this change only on 10.8, as that is where we appear to be seeing this (mostly?). Anyone having a preference to this 10.8 alternative?
        Hide
        Myrna van Lunteren added a comment -

        reattaching the file, after renaming it to _3.diff, so I can flag the grant to ASF button.

        Show
        Myrna van Lunteren added a comment - reattaching the file, after renaming it to _3.diff, so I can flag the grant to ASF button.
        Hide
        Myrna van Lunteren added a comment -

        patch available for review

        Show
        Myrna van Lunteren added a comment - patch available for review
        Hide
        Kathey Marsden added a comment -

        Thank you Myna for the patch.
        I think printing the missing expected results and the actual results as part of the failure is a good idea but since actual and expected are Array's, I think the following won't print the contents of the array, just the Array object reference.

        + String message = "Missing rows in ResultSet; expected rows: \n\t"
        + + expected + ", actual result: \n\t" + actual;

        Otherwise the patch looks fine to me. My vote is to put it into trunk and backport to 10.8. I generally don't like to dead end anything in a branch unless it is an alternate fix to a trunk fix.

        Show
        Kathey Marsden added a comment - Thank you Myna for the patch. I think printing the missing expected results and the actual results as part of the failure is a good idea but since actual and expected are Array's, I think the following won't print the contents of the array, just the Array object reference. + String message = "Missing rows in ResultSet; expected rows: \n\t" + + expected + ", actual result: \n\t" + actual; Otherwise the patch looks fine to me. My vote is to put it into trunk and backport to 10.8. I generally don't like to dead end anything in a branch unless it is an alternate fix to a trunk fix.
        Hide
        Myrna van Lunteren added a comment -

        Thanks for the review and input, Kathey.
        But 'actual' and 'expected' are not Arrays, but ArrayLists. To my delight, ArrayList has a toString() method that seems sufficient to print out further info.
        (ArrayList.toString():
        Returns a string representation of this collection. The string representation consists of a list of the collection's elements in the order they are returned by its iterator, enclosed in square brackets ("[]"). Adjacent elements are separated by the characters ", " (comma and space). Elements are converted to strings as by String.valueOf(Object). )

        I modified the placings of \n and \t a little since I created my patch.
        To see what we'd get if the test failed, for debugging, I moved the creation of the 'message' String out of the if block, added a println, and ran UpdateLocksTest. I got output like this:
        expected rows:
        [[APP, UserTran, TABLE, 1, IX, A, Tablelock, GRANT, ACTIVE]],
        actual result:
        [[APP, UserTran, TABLE, 1, IX, A, Tablelock, GRANT, ACTIVE]]

        Show
        Myrna van Lunteren added a comment - Thanks for the review and input, Kathey. But 'actual' and 'expected' are not Arrays, but ArrayLists. To my delight, ArrayList has a toString() method that seems sufficient to print out further info. (ArrayList.toString(): Returns a string representation of this collection. The string representation consists of a list of the collection's elements in the order they are returned by its iterator, enclosed in square brackets ("[]"). Adjacent elements are separated by the characters ", " (comma and space). Elements are converted to strings as by String.valueOf(Object). ) I modified the placings of \n and \t a little since I created my patch. To see what we'd get if the test failed, for debugging, I moved the creation of the 'message' String out of the if block, added a println, and ran UpdateLocksTest. I got output like this: expected rows: [ [APP, UserTran, TABLE, 1, IX, A, Tablelock, GRANT, ACTIVE] ], actual result: [ [APP, UserTran, TABLE, 1, IX, A, Tablelock, GRANT, ACTIVE] ]
        Hide
        Myrna van Lunteren added a comment -

        Attaching a patch that is just like the previous DERBY-5667_3.diff, except that there's some minor changes in the location of the returns and tabs, to facilitate visual comparison in the output.

        I will commit this shortly to trunk, then port it back to 10.9 and 10.8 later.

        Show
        Myrna van Lunteren added a comment - Attaching a patch that is just like the previous DERBY-5667 _3.diff, except that there's some minor changes in the location of the returns and tabs, to facilitate visual comparison in the output. I will commit this shortly to trunk, then port it back to 10.9 and 10.8 later.
        Hide
        Myrna van Lunteren added a comment -

        committed patch _3b.diff to trunk with revision: http://svn.apache.org/viewvc?view=revision&revision=1370058

        Show
        Myrna van Lunteren added a comment - committed patch _3b.diff to trunk with revision: http://svn.apache.org/viewvc?view=revision&revision=1370058
        Hide
        Myrna van Lunteren added a comment -

        Attaching a patch which is the result of svn merge -c for UpdateLocksTest, but JDBC.java needed manual adjustment.

        I will to commit this shortly.

        Show
        Myrna van Lunteren added a comment - Attaching a patch which is the result of svn merge -c for UpdateLocksTest, but JDBC.java needed manual adjustment. I will to commit this shortly.
        Hide
        Myrna van Lunteren added a comment -

        committed patch _3_109.diff to 10.9 with revision: http://svn.apache.org/viewvc?view=revision&revision=1370647

        Show
        Myrna van Lunteren added a comment - committed patch _3_109.diff to 10.9 with revision: http://svn.apache.org/viewvc?view=revision&revision=1370647
        Hide
        Myrna van Lunteren added a comment -

        committed backport of revison 1370647 from 10.9 branch to 10.8 (clean merge using svn merge -c 1370647 https://svn.apache.org/repos/asf/db/derby/code/branches/10.9), see: http://svn.apache.org/viewvc?view=revision&revision=1371433

        Show
        Myrna van Lunteren added a comment - committed backport of revison 1370647 from 10.9 branch to 10.8 (clean merge using svn merge -c 1370647 https://svn.apache.org/repos/asf/db/derby/code/branches/10.9 ), see: http://svn.apache.org/viewvc?view=revision&revision=1371433
        Hide
        Myrna van Lunteren added a comment -

        I think this issue has been resolved.

        Show
        Myrna van Lunteren added a comment - I think this issue has been resolved.
        Hide
        Myrna van Lunteren added a comment -

        This failed again on the 10.8 branch, with ibm 1.4.2, linux, see:
        http://people.apache.org/~myrnavl/derby_test_results/v10_8/linux/testlog/ibm142/1566493-suites.All_diff.txt
        testReadUncommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Unexpected row count expected:<3> but was:<2>
        at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code))
        at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code))
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeCursorLocks2(UpdateLocksTest.java:5874)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:337)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testReadUncommitted(UpdateLocksTest.java:168)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Compiled Code))
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Compiled Code))
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java(Compiled Code))
        at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java(Compiled Code))
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)

        Interestingly, I can now duplicate this behavior very easily on my machine with 10.8 classes and running the store suite.
        I narrowed it down to (apparently) a cleanup issue in the test Derby4676Test.java.
        I will work on an improved cleanup.

        Show
        Myrna van Lunteren added a comment - This failed again on the 10.8 branch, with ibm 1.4.2, linux, see: http://people.apache.org/~myrnavl/derby_test_results/v10_8/linux/testlog/ibm142/1566493-suites.All_diff.txt testReadUncommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Unexpected row count expected:<3> but was:<2> at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code)) at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code)) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeCursorLocks2(UpdateLocksTest.java:5874) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:337) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testReadUncommitted(UpdateLocksTest.java:168) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Compiled Code)) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java(Compiled Code)) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java(Compiled Code)) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java(Compiled Code)) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) Interestingly, I can now duplicate this behavior very easily on my machine with 10.8 classes and running the store suite. I narrowed it down to (apparently) a cleanup issue in the test Derby4676Test.java. I will work on an improved cleanup.
        Hide
        Myrna van Lunteren added a comment - - edited

        On closer look, it's not that simple.

        I think there is an issue with ibm 1.4.2 and Thread maintenance, I believe we have seen other instances of trouble.
        If ,with 10.8 classes and ibm 1.4.2, I have only the Derby4676Test run before UpdateLocksTest, then on my system, there are always one or more failures in the UpdateLocksTest.
        With ibm 1.5 or higher, all is fine.
        If I do not have Derby4676Test, all is fine.
        If I only have embeddedSuite for Derby4676Test, all is fine in UpdateLocksTest also.
        If I only have clientServerSuite for Derby4676Test, all is fine in UpdateLocksTest also.
        But if I have defaultSuite, the UpdateLocksTest fails with ibm 1.4.2

        I have tried to put waitforPostCommit calls in various places in the teardown, but it does not appear to matter.

        At this point, I propose to make the Derby4676Test to only run in embedded with ibm 1.4.2 on 10.8. I do not intend to make this change on any other branch, even on 10.8 I do not really expect anyone to run with 1.4.2 anymore.

        Show
        Myrna van Lunteren added a comment - - edited On closer look, it's not that simple. I think there is an issue with ibm 1.4.2 and Thread maintenance, I believe we have seen other instances of trouble. If ,with 10.8 classes and ibm 1.4.2, I have only the Derby4676Test run before UpdateLocksTest, then on my system, there are always one or more failures in the UpdateLocksTest. With ibm 1.5 or higher, all is fine. If I do not have Derby4676Test, all is fine. If I only have embeddedSuite for Derby4676Test, all is fine in UpdateLocksTest also. If I only have clientServerSuite for Derby4676Test, all is fine in UpdateLocksTest also. But if I have defaultSuite, the UpdateLocksTest fails with ibm 1.4.2 I have tried to put waitforPostCommit calls in various places in the teardown, but it does not appear to matter. At this point, I propose to make the Derby4676Test to only run in embedded with ibm 1.4.2 on 10.8. I do not intend to make this change on any other branch, even on 10.8 I do not really expect anyone to run with 1.4.2 anymore.
        Hide
        Myrna van Lunteren added a comment -

        Unfortunately, when I ran the normal length store._Suite, UpdateLocksTest failed again.
        When I eliminate the Derby4676Test altogether, then the UpdateLocksTest passes...

        Show
        Myrna van Lunteren added a comment - Unfortunately, when I ran the normal length store._Suite, UpdateLocksTest failed again. When I eliminate the Derby4676Test altogether, then the UpdateLocksTest passes...
        Hide
        Myrna van Lunteren added a comment -

        I made a little modification in JDBC.assertUnorderedResultSet, and added a commit to UpdateLocksTest.teardown, and this resulted in the following test output (ibm 1.4.2, 10.8, on my windows 7 laptop):

        (emb)store.Derby4676Test.testConcurrentFetchAndDelete used 4817 ms .
        (net)store.Derby4676Test.testConcurrentFetchAndDelete used 4103 ms .
        (emb)store.UpdateLocksTest.testRepeatableRead used 3814 ms .
        (emb)store.UpdateLocksTest.testReadCommitted used 3401 ms .
        (emb)store.UpdateLocksTest.testSerializable used 3568 ms F.
        (emb)store.UpdateLocksTest.testReadUncommitted used 1773 ms F
        Time: 28.754
        There were 2 failures:
        1) testSerializable(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Unexpected row count, expected: 2, actual: 3
        expected rows:
        [[APP, UserTran, TABLE, 2, IX, A, Tablelock, GRANT, ACTIVE], [APP, UserTran, ROW, 3, X, A, (1,9), GRANT, ACTIVE]]
        actual result:
        [[APP, UserTran, TABLE, 2, IX, A, Tablelock, GRANT, ACTIVE], [APP, UserTran, ROW, 1, U, A, (1,9), GRANT, ACTIVE], [APP, UserTran, ROW, 2, X, A, (1,9), GRANT, ACTIVE]] expected:<2> but was:<3>
        at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code))
        at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java:1304)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeSetLocks(UpdateLocksTest.java:7028)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:254)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testSerializable(UpdateLocksTest.java:166)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:61)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java(Compiled Code))
        at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        2) testReadUncommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Unexpected row count, expected: 3, actual: 2
        expected rows:
        [[APP, UserTran, TABLE, 2, IX, A, Tablelock, GRANT, ACTIVE], [APP, UserTran, ROW, 1, X, A, (1,10), GRANT, ACTIVE], [APP, UserTran, ROW, 3, X, A, (1,9), GRANT, ACTIVE]]
        actual result:
        [[APP, UserTran, TABLE, 2, IX, A, Tablelock, GRANT, ACTIVE], [APP, UserTran, ROW, 2, X, A, (1,9), GRANT, ACTIVE]] expected:<3> but was:<2>
        at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code))
        at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java:1304)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeSetLocks(UpdateLocksTest.java:7472)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:266)
        at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testReadUncommitted(UpdateLocksTest.java:170)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:61)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java(Compiled Code))
        at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)

        It is surprising that I can make UpdateLocksTest fail when run after Derby4676Test. But if we're assuming that there issue is background threads from the deletes in the earlier test, then why doesn't that show up in the first test cases?

        I can modify the 10.8 store._Suite so it runs the two tests in reverse order with ibm 1.4.2.
        But I would like to understand a bit more, in case failures pop up again in UpdateLocksTest on later branches with newer jvms.

        Show
        Myrna van Lunteren added a comment - I made a little modification in JDBC.assertUnorderedResultSet, and added a commit to UpdateLocksTest.teardown, and this resulted in the following test output (ibm 1.4.2, 10.8, on my windows 7 laptop): (emb)store.Derby4676Test.testConcurrentFetchAndDelete used 4817 ms . (net)store.Derby4676Test.testConcurrentFetchAndDelete used 4103 ms . (emb)store.UpdateLocksTest.testRepeatableRead used 3814 ms . (emb)store.UpdateLocksTest.testReadCommitted used 3401 ms . (emb)store.UpdateLocksTest.testSerializable used 3568 ms F. (emb)store.UpdateLocksTest.testReadUncommitted used 1773 ms F Time: 28.754 There were 2 failures: 1) testSerializable(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Unexpected row count, expected: 2, actual: 3 expected rows: [ [APP, UserTran, TABLE, 2, IX, A, Tablelock, GRANT, ACTIVE] , [APP, UserTran, ROW, 3, X, A, (1,9), GRANT, ACTIVE] ] actual result: [ [APP, UserTran, TABLE, 2, IX, A, Tablelock, GRANT, ACTIVE] , [APP, UserTran, ROW, 1, U, A, (1,9), GRANT, ACTIVE] , [APP, UserTran, ROW, 2, X, A, (1,9), GRANT, ACTIVE] ] expected:<2> but was:<3> at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code)) at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java:1304) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeSetLocks(UpdateLocksTest.java:7028) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:254) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testSerializable(UpdateLocksTest.java:166) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:61) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java(Compiled Code)) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) 2) testReadUncommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Unexpected row count, expected: 3, actual: 2 expected rows: [ [APP, UserTran, TABLE, 2, IX, A, Tablelock, GRANT, ACTIVE] , [APP, UserTran, ROW, 1, X, A, (1,10), GRANT, ACTIVE] , [APP, UserTran, ROW, 3, X, A, (1,9), GRANT, ACTIVE] ] actual result: [ [APP, UserTran, TABLE, 2, IX, A, Tablelock, GRANT, ACTIVE] , [APP, UserTran, ROW, 2, X, A, (1,9), GRANT, ACTIVE] ] expected:<3> but was:<2> at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java(Compiled Code)) at org.apache.derbyTesting.junit.JDBC.assertUnorderedResultSet(JDBC.java:1304) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.updateBtreeSetLocks(UpdateLocksTest.java:7472) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.doRunTests(UpdateLocksTest.java:266) at org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest.testReadUncommitted(UpdateLocksTest.java:170) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:61) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java(Compiled Code)) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) It is surprising that I can make UpdateLocksTest fail when run after Derby4676Test. But if we're assuming that there issue is background threads from the deletes in the earlier test, then why doesn't that show up in the first test cases? I can modify the 10.8 store._Suite so it runs the two tests in reverse order with ibm 1.4.2. But I would like to understand a bit more, in case failures pop up again in UpdateLocksTest on later branches with newer jvms.
        Hide
        Mike Matrigali added a comment -

        I looked closely at the first failure in your recent posting, a failure in testSerializable, with updateBtreeSetLocks. This test is expecting a query plan to use the index. The difference is rather than 3 X row locks, we end up with 2 X row locks and a U lock.

        The query is:
        /* ------------------------------------------------------------

        • Test updates an exact match on a with base row qualification
        • necessary.
          *
        • At this point the table should look like:
        • 1, 10, 'one'
        • 3, 300, 'three'
        • 5, 50, 'five'
        • 7, 70, 'seven'
        • ------------------------------------------------------------
          */
          s.executeUpdate(
          "update a set b = 30 where a = 3 and b = 300");

        There is a index on a, and query needs to go to base table to read and write b.

        I think the expected locks are:
        look up a=3 in index (IX table on a, X lock on row a=3)
        find base row and get value b (X lock on row a=3, b=300 in base table)
        separate step to update the value in base table (IX table on a, X lock on row a=3, b=300)

        I believe we actually in-line ask for a U row lock first at some point and then escalate
        it to X when we have gotten it and know we are going to do the update. I don't know
        why a U lock would be left around in any case. It would not cause any problem because the xact already has X lock until end transaction so the U lock becomes
        meaningless.

        The lock count is an internal implementation detail and probably should not have
        been exposed, but doing that would have been more work than just dumping the
        lock table state. And originally the tool really was more for debugging the lock
        manager than providing something for users.

        I looked closely and it looks like the code handles committed deletes with proper wait for post commit.

        So, given you are seeing intermittent issues, I started wondering if it could be related to the other background timing issue with tests - the automatic statistics gatherer. This test has very few rows and in this test case I think all the rows fit on one page of index and one page of a data page. I could see the optmizer picking
        a different plan with a change of statistics. I sugest turning off the statistics gatherer for all locking tests like these
        that expect to own exactly how the query will be executed.

        Show
        Mike Matrigali added a comment - I looked closely at the first failure in your recent posting, a failure in testSerializable, with updateBtreeSetLocks. This test is expecting a query plan to use the index. The difference is rather than 3 X row locks, we end up with 2 X row locks and a U lock. The query is: /* ------------------------------------------------------------ Test updates an exact match on a with base row qualification necessary. * At this point the table should look like: 1, 10, 'one' 3, 300, 'three' 5, 50, 'five' 7, 70, 'seven' ------------------------------------------------------------ */ s.executeUpdate( "update a set b = 30 where a = 3 and b = 300"); There is a index on a, and query needs to go to base table to read and write b. I think the expected locks are: look up a=3 in index (IX table on a, X lock on row a=3) find base row and get value b (X lock on row a=3, b=300 in base table) separate step to update the value in base table (IX table on a, X lock on row a=3, b=300) I believe we actually in-line ask for a U row lock first at some point and then escalate it to X when we have gotten it and know we are going to do the update. I don't know why a U lock would be left around in any case. It would not cause any problem because the xact already has X lock until end transaction so the U lock becomes meaningless. The lock count is an internal implementation detail and probably should not have been exposed, but doing that would have been more work than just dumping the lock table state. And originally the tool really was more for debugging the lock manager than providing something for users. I looked closely and it looks like the code handles committed deletes with proper wait for post commit. So, given you are seeing intermittent issues, I started wondering if it could be related to the other background timing issue with tests - the automatic statistics gatherer. This test has very few rows and in this test case I think all the rows fit on one page of index and one page of a data page. I could see the optmizer picking a different plan with a change of statistics. I sugest turning off the statistics gatherer for all locking tests like these that expect to own exactly how the query will be executed.
        Hide
        Mike Matrigali added a comment - - edited

        the second failure:
        2) testReadUncommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Unexpected row count, expected: 3, actual: 2
        expected rows:
        [[APP, UserTran, TABLE, 2, IX, A, Tablelock, GRANT, ACTIVE], [APP, UserTran, ROW, 1, X, A, (1,10), GRANT, ACTIVE], [APP, UserTran, ROW, 3, X, A, (1,9), GRANT, ACTIVE]]
        actual result:
        [[APP, UserTran, TABLE, 2, IX, A, Tablelock, GRANT, ACTIVE], [APP, UserTran, ROW, 2, X, A, (1,9), GRANT, ACTIVE]] expected:<3> but was:<2>

        In this case we expected X row locks on both rows in the table since the scan is a range
        that includes both rows. But we only got locks on one row, can't tell from the output but
        have to assume it is on the one qualifying row. This does have the feel of a different
        execution plan for some reason.

        /* ------------------------------------------------------------

        • Test qualified full cursor scan which updates a row.
          *
        • At this point the table should look like:
        • 3, -30, '-three'
        • 5, -50, 'five'
        • ------------------------------------------------------------
          */
          s.executeUpdate(
          "update a set b = 30 where a > 2 and a < 5");
        Show
        Mike Matrigali added a comment - - edited the second failure: 2) testReadUncommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Unexpected row count, expected: 3, actual: 2 expected rows: [ [APP, UserTran, TABLE, 2, IX, A, Tablelock, GRANT, ACTIVE] , [APP, UserTran, ROW, 1, X, A, (1,10), GRANT, ACTIVE] , [APP, UserTran, ROW, 3, X, A, (1,9), GRANT, ACTIVE] ] actual result: [ [APP, UserTran, TABLE, 2, IX, A, Tablelock, GRANT, ACTIVE] , [APP, UserTran, ROW, 2, X, A, (1,9), GRANT, ACTIVE] ] expected:<3> but was:<2> In this case we expected X row locks on both rows in the table since the scan is a range that includes both rows. But we only got locks on one row, can't tell from the output but have to assume it is on the one qualifying row. This does have the feel of a different execution plan for some reason. /* ------------------------------------------------------------ Test qualified full cursor scan which updates a row. * At this point the table should look like: 3, -30, '-three' 5, -50, 'five' ------------------------------------------------------------ */ s.executeUpdate( "update a set b = 30 where a > 2 and a < 5");
        Hide
        Myrna van Lunteren added a comment - - edited

        The failures (still only with ibm 1.4.2 and only if I run Derby4676Test first) are always in the method UpdateLocksTest.updateBtreeSetLocks, and always in the checks after a delete or update, but before commit. I've seen all of them fail at one point or another. I've seen test failures in all the isolations in differing combinations. The test mostly repeats the same checks after a commit and those are always fine.

        I've thought of updating runtimestatistics before the check, but that seems to only cause additional IS locks. I could do a commit after the runtimestatistics call, but that would make the checks unnecessary because we already have the one after commit.

        I have tried to make the UpdateLocksTest bounce the database, from the comments this should happen when you pass 'true' as the third argument to the SystemPropertyTestSetup, but that did not change the behavior.

        Although it's still mysterious that this pops when I run the Derby4676Test first, I think at this point I am satisfied that for some reason it makes the optimizer like a different plan. The instability remains possible and only if we modify the entire test and make a search for only those locks we are really after will this be completely eliminated. I do not intend to make that effort at this time.

        I will do the following:
        for all branches

        • add a commit() to the teardown in UpdateLocksTest so it doesn't choke in attempting to create 'A' table for subsequent test fixtures if one fails
        • expand the error reporting in JDBC.assertUnorderedResultSet to show any missing rows
          only for 10.8:
        • add a private method (assertUnorderedResultSet) in UpdateLocksTest which just returns if the jvm is ibm142, and calls the public JDBC.assertUnorderedResultSet otherwise, and use this method in the problematic calls in UpdateLocksTest.updateBtreeSetLocks.
        Show
        Myrna van Lunteren added a comment - - edited The failures (still only with ibm 1.4.2 and only if I run Derby4676Test first) are always in the method UpdateLocksTest.updateBtreeSetLocks, and always in the checks after a delete or update, but before commit. I've seen all of them fail at one point or another. I've seen test failures in all the isolations in differing combinations. The test mostly repeats the same checks after a commit and those are always fine. I've thought of updating runtimestatistics before the check, but that seems to only cause additional IS locks. I could do a commit after the runtimestatistics call, but that would make the checks unnecessary because we already have the one after commit. I have tried to make the UpdateLocksTest bounce the database, from the comments this should happen when you pass 'true' as the third argument to the SystemPropertyTestSetup, but that did not change the behavior. Although it's still mysterious that this pops when I run the Derby4676Test first, I think at this point I am satisfied that for some reason it makes the optimizer like a different plan. The instability remains possible and only if we modify the entire test and make a search for only those locks we are really after will this be completely eliminated. I do not intend to make that effort at this time. I will do the following: for all branches add a commit() to the teardown in UpdateLocksTest so it doesn't choke in attempting to create 'A' table for subsequent test fixtures if one fails expand the error reporting in JDBC.assertUnorderedResultSet to show any missing rows only for 10.8: add a private method (assertUnorderedResultSet) in UpdateLocksTest which just returns if the jvm is ibm142, and calls the public JDBC.assertUnorderedResultSet otherwise, and use this method in the problematic calls in UpdateLocksTest.updateBtreeSetLocks.
        Hide
        ASF subversion and git services added a comment -

        Commit 1567787 from Myrna van Lunteren in branch 'code/trunk'
        [ https://svn.apache.org/r1567787 ]

        DERBY-5667; testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet
        further improving error message in assert, and avoiding error message re table exists if a test case fails

        Show
        ASF subversion and git services added a comment - Commit 1567787 from Myrna van Lunteren in branch 'code/trunk' [ https://svn.apache.org/r1567787 ] DERBY-5667 ; testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet further improving error message in assert, and avoiding error message re table exists if a test case fails
        Hide
        ASF subversion and git services added a comment -

        Commit 1567823 from Myrna van Lunteren in branch 'code/branches/10.10'
        [ https://svn.apache.org/r1567823 ]

        DERBY-5667; testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet
        backport of revision 1567787 from trunk - improve error message

        Show
        ASF subversion and git services added a comment - Commit 1567823 from Myrna van Lunteren in branch 'code/branches/10.10' [ https://svn.apache.org/r1567823 ] DERBY-5667 ; testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet backport of revision 1567787 from trunk - improve error message
        Hide
        ASF subversion and git services added a comment -

        Commit 1567826 from Myrna van Lunteren in branch 'code/branches/10.9'
        [ https://svn.apache.org/r1567826 ]

        DERBY-5667; testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet
        backport of revision 1567823 from trunk, not a clean merge of JDBC.java

        Show
        ASF subversion and git services added a comment - Commit 1567826 from Myrna van Lunteren in branch 'code/branches/10.9' [ https://svn.apache.org/r1567826 ] DERBY-5667 ; testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet backport of revision 1567823 from trunk, not a clean merge of JDBC.java
        Hide
        ASF subversion and git services added a comment -

        Commit 1567828 from Myrna van Lunteren in branch 'code/branches/10.8'
        [ https://svn.apache.org/r1567828 ]

        DERBY-5667; testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet
        merge of revision 1567826 from 10.9 branch

        Show
        ASF subversion and git services added a comment - Commit 1567828 from Myrna van Lunteren in branch 'code/branches/10.8' [ https://svn.apache.org/r1567828 ] DERBY-5667 ; testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet merge of revision 1567826 from 10.9 branch
        Hide
        ASF subversion and git services added a comment -

        Commit 1567831 from Myrna van Lunteren in branch 'code/branches/10.8'
        [ https://svn.apache.org/r1567831 ]

        DERBY-5667; testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet
        making part of the tests' checks skip with ibm 1.4.2.

        Show
        ASF subversion and git services added a comment - Commit 1567831 from Myrna van Lunteren in branch 'code/branches/10.8' [ https://svn.apache.org/r1567831 ] DERBY-5667 ; testReadCommitted(org.apache.derbyTesting.functionTests.tests.store.UpdateLocksTest)junit.framework.AssertionFailedError: Missing rows in ResultSet making part of the tests' checks skip with ibm 1.4.2.
        Hide
        Myrna van Lunteren added a comment -

        Although several improvements have gone in (some improved error messaging, and especially, adding of calls to wait for background commit tasks), and I've added skipping of one set of checks that failed on one particular machine with one particular JVM in the 10.8 branch, it is still possible that this test might show instability. To eliminate that, we'd have to go through this test and figure out in each case, which lock we're really interested in, and look for that one only.

        I do not intend to do that at this time, so I am closing this issue as 'Won't Fix'. If this failure becomes prevalent, we can re-evaluate.

        Show
        Myrna van Lunteren added a comment - Although several improvements have gone in (some improved error messaging, and especially, adding of calls to wait for background commit tasks), and I've added skipping of one set of checks that failed on one particular machine with one particular JVM in the 10.8 branch, it is still possible that this test might show instability. To eliminate that, we'd have to go through this test and figure out in each case, which lock we're really interested in, and look for that one only. I do not intend to do that at this time, so I am closing this issue as 'Won't Fix'. If this failure becomes prevalent, we can re-evaluate.

          People

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

            Dates

            • Created:
              Updated:
              Resolved:

              Development