Derby
  1. Derby
  2. DERBY-4825

Assert failure in LargeDataLocksTest.testGetCharacterStream() because of wrong number of locks

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 10.6.2.1
    • Fix Version/s: 10.7.1.1
    • Component/s: Test
    • Labels:
      None
    • Environment:
      FreeBSD 8.1, i386
      Diablo Java(TM) SE Runtime Environment (build 1.6.0_07-b02)
    • Bug behavior facts:
      Regression Test Failure

      Description

      I saw this failure when running suites.All on the 10.6.2.1 release candidate:

      1) testGetCharacterStream(org.apache.derbyTesting.functionTests.tests.jdbcapi.LargeDataLocksTest)junit.framework.AssertionFailedError: expected:<0> but was:<3>
      at org.apache.derbyTesting.functionTests.tests.jdbcapi.LargeDataLocksTest.testGetCharacterStream(LargeDataLocksTest.java:72)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:109)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:23)
      at junit.extensions.TestSetup.run(TestSetup.java:27)
      at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)

      The assertion expects the lock table to have zero locks, but it finds three.

      The test succeeded when I later ran it 100 times outside of suites.All.

      The failure looks similar to DERBY-4301, but I saw this in a pure 10.6 environment, whereas DERBY-4301 happened in a mixed 10.3/10.5 environment. Also, DERBY-4301 is consistently reproducible, whereas this failure appears to be intermittent.

      1. postcommit.diff
        2 kB
        Knut Anders Hatlen
      2. dump-locks.diff
        3 kB
        Knut Anders Hatlen

        Issue Links

          Activity

          Hide
          Knut Anders Hatlen added a comment -

          Committed revision 1006332.

          Show
          Knut Anders Hatlen added a comment - Committed revision 1006332.
          Hide
          Knut Anders Hatlen added a comment -

          suites.All ran cleanly the second time with the patch too.

          Show
          Knut Anders Hatlen added a comment - suites.All ran cleanly the second time with the patch too.
          Hide
          Knut Anders Hatlen added a comment -

          I found that the background thread obtains exclusive locks on rows the SYSSTATEMENTS table while doing post-commit work, so I suspect that's what making these locks turn up intermittently in the lock table.

          The attached patch makes assertLockCount() wait for post-commit work to complete before it counts the locks. On a machine where LargeDataLocksTest has failed every time I've run it as part of suites.All, the entire test suite ran cleanly with the patch. I'll rerun suites.All to verify that it wasn't just pure luck that made it pass this one time. (I have never seen the failure outside of suites.All, so I don't have any quicker way to verify it.)

          If we make this change, I don't think we should move assertLockCount() to BaseJDBCTestCase just yet since it now depends on a stored procedure that won't be available in general.

          Show
          Knut Anders Hatlen added a comment - I found that the background thread obtains exclusive locks on rows the SYSSTATEMENTS table while doing post-commit work, so I suspect that's what making these locks turn up intermittently in the lock table. The attached patch makes assertLockCount() wait for post-commit work to complete before it counts the locks. On a machine where LargeDataLocksTest has failed every time I've run it as part of suites.All, the entire test suite ran cleanly with the patch. I'll rerun suites.All to verify that it wasn't just pure luck that made it pass this one time. (I have never seen the failure outside of suites.All, so I don't have any quicker way to verify it.) If we make this change, I don't think we should move assertLockCount() to BaseJDBCTestCase just yet since it now depends on a stored procedure that won't be available in general.
          Hide
          Kristian Waagan added a comment -

          > But I guess in most cases where you're interested in the
          > contents of the lock table you would have an assert of some kind.

          Yes, except when you are trying to understand when and where locks are being set during a debugging session. This code would only be enabled temporarily, I don't expect it to ever be committed.

          In any case, moving the current method would be a good incremental improvement in my opinion, as it gives you better information when the test fails.

          Show
          Kristian Waagan added a comment - > But I guess in most cases where you're interested in the > contents of the lock table you would have an assert of some kind. Yes, except when you are trying to understand when and where locks are being set during a debugging session. This code would only be enabled temporarily, I don't expect it to ever be committed. In any case, moving the current method would be a good incremental improvement in my opinion, as it gives you better information when the test fails.
          Hide
          Knut Anders Hatlen added a comment -

          > I have been writing similar code myself many times when debugging,
          > and I think it would be a nice addition to the test framework. Do
          > we have an appropriate home for such a method?

          I suppose we could move this method to BaseJDBCTestCase to make it
          available for other tests.

          > It would also be nice to have a method do just dump the lock table
          > to stdout (i.e. not doing any asserts).

          I see that there are some tests with helper methods that print result
          sets to stdout. Perhaps one of those can be moved to the
          BaseJDBCTestCase class or the JDBC class? But I guess in most cases
          where you're interested in the contents of the lock table you would
          have an assert of some kind.

          Show
          Knut Anders Hatlen added a comment - > I have been writing similar code myself many times when debugging, > and I think it would be a nice addition to the test framework. Do > we have an appropriate home for such a method? I suppose we could move this method to BaseJDBCTestCase to make it available for other tests. > It would also be nice to have a method do just dump the lock table > to stdout (i.e. not doing any asserts). I see that there are some tests with helper methods that print result sets to stdout. Perhaps one of those can be moved to the BaseJDBCTestCase class or the JDBC class? But I guess in most cases where you're interested in the contents of the lock table you would have an assert of some kind.
          Hide
          Knut Anders Hatlen added a comment -

          Committed the patch with revision 1004609 so that we get more info when the test fails.

          Show
          Knut Anders Hatlen added a comment - Committed the patch with revision 1004609 so that we get more info when the test fails.
          Hide
          Kristian Waagan added a comment -

          I have been writing similar code myself many times when debugging, and I think it would be a nice addition to the test framework.
          Do we have an appropriate home for such a method?

          It would also be nice to have a method do just dump the lock table to stdout (i.e. not doing any asserts).

          Show
          Kristian Waagan added a comment - I have been writing similar code myself many times when debugging, and I think it would be a nice addition to the test framework. Do we have an appropriate home for such a method? It would also be nice to have a method do just dump the lock table to stdout (i.e. not doing any asserts).
          Hide
          Knut Anders Hatlen added a comment -

          Attaching a patch that makes LargeDataLocksTest report the contents of the lock table when the lock count is wrong. I now see this message when I run suites.All:

          junit.framework.AssertionFailedError: Unexpected lock count. Contents of lock table:
          1: XID=601052 TYPE=ROW MODE=X TABLENAME=SYSSTATEMENTS LOCKNAME=(10,13) STATE=GRANT TABLETYPE=S LOCKCOUNT=1 INDEXNAME=null
          2: XID=601052 TYPE=TABLE MODE=IX TABLENAME=SYSSTATEMENTS LOCKNAME=Tablelock STATE=GRANT TABLETYPE=S LOCKCOUNT=1 INDEXNAME=null
          expected:<0> but was:<2>

          Exclusive locks in SYSSTATEMENTS would usually mean that someone is recompiling a trigger or a meta-data query, I think.

          Show
          Knut Anders Hatlen added a comment - Attaching a patch that makes LargeDataLocksTest report the contents of the lock table when the lock count is wrong. I now see this message when I run suites.All: junit.framework.AssertionFailedError: Unexpected lock count. Contents of lock table: 1: XID=601052 TYPE=ROW MODE=X TABLENAME=SYSSTATEMENTS LOCKNAME=(10,13) STATE=GRANT TABLETYPE=S LOCKCOUNT=1 INDEXNAME=null 2: XID=601052 TYPE=TABLE MODE=IX TABLENAME=SYSSTATEMENTS LOCKNAME=Tablelock STATE=GRANT TABLETYPE=S LOCKCOUNT=1 INDEXNAME=null expected:<0> but was:<2> Exclusive locks in SYSSTATEMENTS would usually mean that someone is recompiling a trigger or a meta-data query, I think.
          Hide
          Knut Anders Hatlen added a comment -

          Assigning the issue to me while I'm investigating it.

          Show
          Knut Anders Hatlen added a comment - Assigning the issue to me while I'm investigating it.
          Hide
          Knut Anders Hatlen added a comment -

          And it failed when I swapped the Diablo JVM with OpenJDK 6 b19 too. I'll make the test dump the contents of the lock table and see if that gives us a clue.

          Show
          Knut Anders Hatlen added a comment - And it failed when I swapped the Diablo JVM with OpenJDK 6 b19 too. I'll make the test dump the contents of the lock table and see if that gives us a clue.
          Hide
          Knut Anders Hatlen added a comment -

          I reran the entire suites.All on this platform and then it happened again (failed on the same assertion, but lock count was 2 not 3 this time):

          junit.framework.AssertionFailedError: expected:<0> but was:<2>
          at junit.framework.Assert.fail(Assert.java:47)
          at junit.framework.Assert.failNotEquals(Assert.java:283)
          at junit.framework.Assert.assertEquals(Assert.java:64)
          at junit.framework.Assert.assertEquals(Assert.java:195)
          at junit.framework.Assert.assertEquals(Assert.java:201)
          at org.apache.derbyTesting.functionTests.tests.jdbcapi.LargeDataLocksTest.testGetCharacterStream(LargeDataLocksTest.java:72)

          Show
          Knut Anders Hatlen added a comment - I reran the entire suites.All on this platform and then it happened again (failed on the same assertion, but lock count was 2 not 3 this time): junit.framework.AssertionFailedError: expected:<0> but was:<2> at junit.framework.Assert.fail(Assert.java:47) at junit.framework.Assert.failNotEquals(Assert.java:283) at junit.framework.Assert.assertEquals(Assert.java:64) at junit.framework.Assert.assertEquals(Assert.java:195) at junit.framework.Assert.assertEquals(Assert.java:201) at org.apache.derbyTesting.functionTests.tests.jdbcapi.LargeDataLocksTest.testGetCharacterStream(LargeDataLocksTest.java:72)

            People

            • Assignee:
              Knut Anders Hatlen
              Reporter:
              Knut Anders Hatlen
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development