Derby
  1. Derby
  2. DERBY-5377

AssertionFailedError in testCaseCS4595B_NonUniqueIndex in AccessTest

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.8.3.0, 10.9.1.0
    • Fix Version/s: 10.8.3.0, 10.9.1.0
    • Component/s: Store, Test
    • Environment:
      Vista, Java 1.5, trunk
    • Urgency:
      Normal
    • Issue & fix info:
      High Value Fix
    • Bug behavior facts:
      Regression Test Failure

      Description

      There was 1 failure:
      1) testCaseCS4595B_NonUniqueIndex(org.apache.derbyTesting.functionTests.tests.store.AccessTest)junit.framework.AssertionFailedError
      at org.apache.derbyTesting.functionTests.tests.store.AccessTest.assertStatsOK(AccessTest.java:402)
      at org.apache.derbyTesting.functionTests.tests.store.AccessTest.doTestCaseCS4595B(AccessTest.java:1720)
      at org.apache.derbyTesting.functionTests.tests.store.AccessTest.testCaseCS4595B_NonUniqueIndex(AccessTest.java:1830)
      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:112)
      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)
      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)

      Cf. http://dbtg.foundry.sun.com/derby/test/Daily/jvm1.5/testing/Limited/testSummary-1154534.html

      1. d5377-dump-stats.diff
        2 kB
        Knut Anders Hatlen
      2. DERBY-5377_try1.diff
        2 kB
        Myrna van Lunteren
      3. DERBY-5377_try2.diff
        3 kB
        Myrna van Lunteren

        Issue Links

          Activity

          Hide
          Knut Anders Hatlen added a comment -

          [bulk update: close all resolved issues that haven't had any activity the last year]

          Show
          Knut Anders Hatlen added a comment - [bulk update: close all resolved issues that haven't had any activity the last year]
          Hide
          Myrna van Lunteren added a comment -

          Marking resolved, as the bug describes a problem with the test, and that part is fixed.

          The reason why sometimes 2 pages get visited is still unclear, but looks like that isn't a problem since the end result is correct - and that was the purpose of the test case.

          Show
          Myrna van Lunteren added a comment - Marking resolved, as the bug describes a problem with the test, and that part is fixed. The reason why sometimes 2 pages get visited is still unclear, but looks like that isn't a problem since the end result is correct - and that was the purpose of the test case.
          Hide
          Myrna van Lunteren added a comment -

          I have not seen the test fail since I put in the code to not look at the difference.
          Now we won't be confronted with the test failing anymore.

          The question as to why sometimes we see 1 and sometimes 2 pages visited remains, but as the end result is the same, and the performance difference is limited, I've lowered the urgency.

          Show
          Myrna van Lunteren added a comment - I have not seen the test fail since I put in the code to not look at the difference. Now we won't be confronted with the test failing anymore. The question as to why sometimes we see 1 and sometimes 2 pages visited remains, but as the end result is the same, and the performance difference is limited, I've lowered the urgency.
          Hide
          Myrna van Lunteren added a comment -

          Thanks for the review Mike. I had already started committing. I committed the main change with revision 1306596, then noticed I missed actually passing in the null and fixed that with revision 1306600. Backported both to 10.8 with revision 1306620.
          I'll monitor the results on the 10.8 windows testing machine where this issue popped up most frequently and report back.

          Show
          Myrna van Lunteren added a comment - Thanks for the review Mike. I had already started committing. I committed the main change with revision 1306596, then noticed I missed actually passing in the null and fixed that with revision 1306600. Backported both to 10.8 with revision 1306620. I'll monitor the results on the 10.8 windows testing machine where this issue popped up most frequently and report back.
          Hide
          Mike Matrigali added a comment -

          +1
          patch looks good to me, and will make understanding nightly results much easier. Once this change is in I would leave bug open but lower priority.

          Show
          Mike Matrigali added a comment - +1 patch looks good to me, and will make understanding nightly results much easier. Once this change is in I would leave bug open but lower priority.
          Hide
          Myrna van Lunteren added a comment -

          I think I have found the other query, I saw the failure in a nightly test output of 3/23:
          http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm142/1304698-suites.All_diff.txt
          -The stack:---
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.assertStatsOK(AccessTest.java:404)
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.doTestCaseCS4595B(AccessTest.java:1727)
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.testCaseCS4595B_NonUniqueIndex(AccessTest.java:1837)
          [...etc...]

          So I'm attaching a modified patch where I'm doing the same trick as with the other two queries.

          I intend to commit this shortly and backport to 10.8.

          Show
          Myrna van Lunteren added a comment - I think I have found the other query, I saw the failure in a nightly test output of 3/23: http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm142/1304698-suites.All_diff.txt - The stack: --- at org.apache.derbyTesting.functionTests.tests.store.AccessTest.assertStatsOK(AccessTest.java:404) at org.apache.derbyTesting.functionTests.tests.store.AccessTest.doTestCaseCS4595B(AccessTest.java:1727) at org.apache.derbyTesting.functionTests.tests.store.AccessTest.testCaseCS4595B_NonUniqueIndex(AccessTest.java:1837) [...etc...] So I'm attaching a modified patch where I'm doing the same trick as with the other two queries. I intend to commit this shortly and backport to 10.8.
          Hide
          Myrna van Lunteren added a comment -

          I'm attaching a possible work around this issue - still assuming there's not really a bug here.

          I looked through the stack traces in this bug description, and matched the 10.8 lines to the same areas in the trunk test, and just passed in 'null' for the expected number of pages; then where we check (assertStatsOK) we're only checking the pages if the values passed in are not null.

          Is this an OK approach?
          I found 2 queries that have this problem, but Mike mentioned 3, so we may need to adjust and do the same with another query.

          Show
          Myrna van Lunteren added a comment - I'm attaching a possible work around this issue - still assuming there's not really a bug here. I looked through the stack traces in this bug description, and matched the 10.8 lines to the same areas in the trunk test, and just passed in 'null' for the expected number of pages; then where we check (assertStatsOK) we're only checking the pages if the values passed in are not null. Is this an OK approach? I found 2 queries that have this problem, but Mike mentioned 3, so we may need to adjust and do the same with another query.
          Hide
          Mike Matrigali added a comment -

          I looked at this and don't understand why the count would be different. The plan looks right to me, which is the point of the tests - the key problem the tests were written for was to insure indexes were being used rather than scans. I think this is a very minor bug, if it is a bug at
          all, and would welcome someone to fix the test to ignore these counts and we could leave the bug open if anyone has any ideas on fixing the
          underlying problem.

          The kind of bug I was looking for given that correct plan was used was more likely a bug in the count of pages visits, maybe
          some caching of this info in the plan statistics rather than actually visiting different number of pages. Again I was never able to reproduce so
          never was able to debug it.

          These page counts were never meant to be exact to the page, and no application should be counting on them.

          Show
          Mike Matrigali added a comment - I looked at this and don't understand why the count would be different. The plan looks right to me, which is the point of the tests - the key problem the tests were written for was to insure indexes were being used rather than scans. I think this is a very minor bug, if it is a bug at all, and would welcome someone to fix the test to ignore these counts and we could leave the bug open if anyone has any ideas on fixing the underlying problem. The kind of bug I was looking for given that correct plan was used was more likely a bug in the count of pages visits, maybe some caching of this info in the plan statistics rather than actually visiting different number of pages. Again I was never able to reproduce so never was able to debug it. These page counts were never meant to be exact to the page, and no application should be counting on them.
          Hide
          Kathey Marsden added a comment -

          Saw this on 3/14 with both IBM 1.6 and 1.7
          http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testSummary-1300803.html

          aside from the difficulty reproducing. I wonder is it indeed incorrect that we visit more than one page?

          Show
          Kathey Marsden added a comment - Saw this on 3/14 with both IBM 1.6 and 1.7 http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testSummary-1300803.html aside from the difficulty reproducing. I wonder is it indeed incorrect that we visit more than one page?
          Hide
          Mike Matrigali added a comment -

          Triage for 10.9. Would be nice to get a fix for this as it is causing pretty regular nightly failures in 10.8.
          I have run test on 10.8 nightly test machine where failures are seen often, and have not been able to reproduce.
          Tried running just the test java file 100 times under load and under no load and no repro.

          Show
          Mike Matrigali added a comment - Triage for 10.9. Would be nice to get a fix for this as it is causing pretty regular nightly failures in 10.8. I have run test on 10.8 nightly test machine where failures are seen often, and have not been able to reproduce. Tried running just the test java file 100 times under load and under no load and no repro.
          Hide
          Mike Matrigali added a comment -

          seen in 10.8 also.

          Show
          Mike Matrigali added a comment - seen in 10.8 also.
          Hide
          Kathey Marsden added a comment -

          Saw again on 10.8 1/27 10.8.2.3 - (1236967) IBM 1.5

          Show
          Kathey Marsden added a comment - Saw again on 10.8 1/27 10.8.2.3 - (1236967) IBM 1.5
          Hide
          Mike Matrigali added a comment -

          saw nightly failure in testCS4595B_PrimaryKey

          Test is expecting 1 page visited and the stat is returning that it visited 2.

          http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm16/1236501-suites.All_diff.txt
          There were 2 failures:
          1) testCS4595B_UniqueIndex(org.apache.derbyTesting.functionTests.tests.store.AccessTest)junit.framework.AssertionFailedError: RuntimeStatisticsParser.findstring(Number of pages visited= 1) returned falsefull runtime statistics = Statement Name:
          null
          Statement Text:
          select a from foo where a = 2
          Parse Time: 0
          Bind Time: 0
          Optimize Time: 0
          Generate Time: 0
          Compile Time: 0
          Execute Time: 0
          Begin Compilation Timestamp : null
          End Compilation Timestamp : null
          Begin Execution Timestamp : null
          End Execution Timestamp : null
          Statement Execution Plan Text:
          Index Scan ResultSet for FOO using index FOOX at serializable isolation level using share row locking chosen by the optimizer
          Number of opens = 1
          Rows seen = 0
          Rows filtered = 0
          Fetch Size = 1
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0

          scan information:
          Bit set of columns fetched=

          {0}

          Number of columns fetched=1
          Number of deleted rows visited=0
          Number of pages visited=2
          Number of rows qualified=0
          Number of rows visited=0
          Scan type=btree
          Tree height=-1
          start position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:
          stop position:
          > on first 1 column(s).
          Ordered null semantics on the following columns:
          qualifiers:
          None
          optimizer estimated row count: 1.00
          optimizer estimated cost: 1.57
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.assertStatsOK(AccessTest.java:404)
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.doTestCaseCS4595B(AccessTest.java:1727)
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.testCS4595B_UniqueIndex(AccessTest.java:1775)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
          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:18)
          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:51)
          at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
          at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
          at junit.extensions.TestSetup.run(TestSetup.java:18)
          2) testCS4595B_UniqueIndex(org.apache.derbyTesting.functionTests.tests.store.AccessTest)junit.framework.AssertionFailedError: RuntimeStatisticsParser.findstring(Number of pages visited= 1) returned falsefull runtime statistics = Statement Name:
          null
          Statement Text:
          select * from foo where a = 2
          Parse Time: 0
          Bind Time: 0
          Optimize Time: 0
          Generate Time: 0
          Compile Time: 0
          Execute Time: 0
          Begin Compilation Timestamp : null
          End Compilation Timestamp : null
          Begin Execution Timestamp : null
          End Execution Timestamp : null
          Statement Execution Plan Text:
          Index Row to Base Row ResultSet for FOO:
          Number of opens = 1
          Rows seen = 0
          Columns accessed from heap =

          {1}

          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 1.00
          optimizer estimated cost: 20.96
          Index Scan ResultSet for FOO using index FOOX at serializable isolation level using share row locking chosen by the optimizer
          Number of opens = 1
          Rows seen = 0
          Rows filtered = 0
          Fetch Size = 1
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0

          scan information:
          Bit set of columns fetched=All
          Number of columns fetched=2
          Number of deleted rows visited=0
          Number of pages visited=2
          Number of rows qualified=0
          Number of rows visited=0
          Scan type=btree
          Tree height=-1
          start position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:
          stop position:
          > on first 1 column(s).
          Ordered null semantics on the following columns:
          qualifiers:
          None
          optimizer estimated row count: 1.00
          optimizer estimated cost: 20.96

          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.assertStatsOK(AccessTest.java:404)
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.doTestCaseCS4595B(AccessTest.java:1715)
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.testCS4595B_UniqueIndex(AccessTest.java:1775)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
          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:18)
          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:51)
          at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
          at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
          at junit.extensions.TestSetup.run(TestSetup.java:18)

          FAILURES!!!
          Tests run: 14054, Failures: 2, Errors: 0

          Show
          Mike Matrigali added a comment - saw nightly failure in testCS4595B_PrimaryKey Test is expecting 1 page visited and the stat is returning that it visited 2. http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm16/1236501-suites.All_diff.txt There were 2 failures: 1) testCS4595B_UniqueIndex(org.apache.derbyTesting.functionTests.tests.store.AccessTest)junit.framework.AssertionFailedError: RuntimeStatisticsParser.findstring(Number of pages visited= 1) returned falsefull runtime statistics = Statement Name: null Statement Text: select a from foo where a = 2 Parse Time: 0 Bind Time: 0 Optimize Time: 0 Generate Time: 0 Compile Time: 0 Execute Time: 0 Begin Compilation Timestamp : null End Compilation Timestamp : null Begin Execution Timestamp : null End Execution Timestamp : null Statement Execution Plan Text: Index Scan ResultSet for FOO using index FOOX at serializable isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 0 Rows filtered = 0 Fetch Size = 1 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 scan information: Bit set of columns fetched= {0} Number of columns fetched=1 Number of deleted rows visited=0 Number of pages visited=2 Number of rows qualified=0 Number of rows visited=0 Scan type=btree Tree height=-1 start position: >= on first 1 column(s). Ordered null semantics on the following columns: stop position: > on first 1 column(s). Ordered null semantics on the following columns: qualifiers: None optimizer estimated row count: 1.00 optimizer estimated cost: 1.57 at org.apache.derbyTesting.functionTests.tests.store.AccessTest.assertStatsOK(AccessTest.java:404) at org.apache.derbyTesting.functionTests.tests.store.AccessTest.doTestCaseCS4595B(AccessTest.java:1727) at org.apache.derbyTesting.functionTests.tests.store.AccessTest.testCS4595B_UniqueIndex(AccessTest.java:1775) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37) 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:18) 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:51) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:18) 2) testCS4595B_UniqueIndex(org.apache.derbyTesting.functionTests.tests.store.AccessTest)junit.framework.AssertionFailedError: RuntimeStatisticsParser.findstring(Number of pages visited= 1) returned falsefull runtime statistics = Statement Name: null Statement Text: select * from foo where a = 2 Parse Time: 0 Bind Time: 0 Optimize Time: 0 Generate Time: 0 Compile Time: 0 Execute Time: 0 Begin Compilation Timestamp : null End Compilation Timestamp : null Begin Execution Timestamp : null End Execution Timestamp : null Statement Execution Plan Text: Index Row to Base Row ResultSet for FOO: Number of opens = 1 Rows seen = 0 Columns accessed from heap = {1} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 1.00 optimizer estimated cost: 20.96 Index Scan ResultSet for FOO using index FOOX at serializable isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 0 Rows filtered = 0 Fetch Size = 1 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 scan information: Bit set of columns fetched=All Number of columns fetched=2 Number of deleted rows visited=0 Number of pages visited=2 Number of rows qualified=0 Number of rows visited=0 Scan type=btree Tree height=-1 start position: >= on first 1 column(s). Ordered null semantics on the following columns: stop position: > on first 1 column(s). Ordered null semantics on the following columns: qualifiers: None optimizer estimated row count: 1.00 optimizer estimated cost: 20.96 at org.apache.derbyTesting.functionTests.tests.store.AccessTest.assertStatsOK(AccessTest.java:404) at org.apache.derbyTesting.functionTests.tests.store.AccessTest.doTestCaseCS4595B(AccessTest.java:1715) at org.apache.derbyTesting.functionTests.tests.store.AccessTest.testCS4595B_UniqueIndex(AccessTest.java:1775) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37) 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:18) 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:51) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:18) FAILURES!!! Tests run: 14054, Failures: 2, Errors: 0
          Hide
          Mike Matrigali added a comment -

          saw nightly failure in testCS4595B_PrimaryKey

          Test is expecting 1 page visited and the stat is returning that it visited 2.

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

          There was 1 failure:
          1) testCS4595B_PrimaryKey(org.apache.derbyTesting.functionTests.tests.store.AccessTest)junit.framework.AssertionFailedError: RuntimeStatisticsParser.findstring(Number of pages visited= 1) returned falsefull runtime statistics = Statement Name:
          null
          Statement Text:
          select * from foo where a = 2
          Parse Time: 0
          Bind Time: 0
          Optimize Time: 0
          Generate Time: 0
          Compile Time: 0
          Execute Time: 0
          Begin Compilation Timestamp : null
          End Compilation Timestamp : null
          Begin Execution Timestamp : null
          End Execution Timestamp : null
          Statement Execution Plan Text:
          Index Row to Base Row ResultSet for FOO:
          Number of opens = 1
          Rows seen = 0
          Columns accessed from heap =

          {1}

          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 1.00
          optimizer estimated cost: 20.96
          Index Scan ResultSet for FOO using constraint SQL120126233210150 at serializable isolation level using share row locking chosen by the optimizer
          Number of opens = 1
          Rows seen = 0
          Rows filtered = 0
          Fetch Size = 1
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0

          scan information:
          Bit set of columns fetched=All
          Number of columns fetched=2
          Number of deleted rows visited=0
          Number of pages visited=2
          Number of rows qualified=0
          Number of rows visited=0
          Scan type=btree
          Tree height=-1
          start position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:
          0
          stop position:
          > on first 1 column(s).
          Ordered null semantics on the following columns:
          0
          qualifiers:
          None
          optimizer estimated row count: 1.00
          optimizer estimated cost: 20.96

          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.assertStatsOK(AccessTest.java:404)
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.doTestCaseCS4595B(AccessTest.java:1715)
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.testCS4595B_PrimaryKey(AccessTest.java:1807)
          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(Inlined Compiled Code))
          at junit.extensions.TestSetup$1.protect(TestSetup.java(Inlined Compiled Code))
          at junit.extensions.TestSetup.run(TestSetup.java(Compiled Code))
          at junit.extensions.TestDecorator.basicRun(TestDecorator.java(Inlined Compiled Code))
          at junit.extensions.TestSetup$1.protect(TestSetup.java(Inlined Compiled Code))
          at junit.extensions.TestSetup.run(TestSetup.java(Compiled Code))
          at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
          at junit.extensions.TestDecorator.basicRun(TestDecorator.java(Inlined Compiled Code))
          at junit.extensions.TestSetup$1.protect(TestSetup.java(Inlined Compiled Code))
          at junit.extensions.TestSetup.run(TestSetup.java(Compiled Code))

          FAILURES!!!
          Tests run: 11966, Failures: 1, Errors: 0

          Show
          Mike Matrigali added a comment - saw nightly failure in testCS4595B_PrimaryKey Test is expecting 1 page visited and the stat is returning that it visited 2. http://people.apache.org/~myrnavl/derby_test_results/v10_8/windows/testlog/ibm142/1236501-suites.All_diff.txt There was 1 failure: 1) testCS4595B_PrimaryKey(org.apache.derbyTesting.functionTests.tests.store.AccessTest)junit.framework.AssertionFailedError: RuntimeStatisticsParser.findstring(Number of pages visited= 1) returned falsefull runtime statistics = Statement Name: null Statement Text: select * from foo where a = 2 Parse Time: 0 Bind Time: 0 Optimize Time: 0 Generate Time: 0 Compile Time: 0 Execute Time: 0 Begin Compilation Timestamp : null End Compilation Timestamp : null Begin Execution Timestamp : null End Execution Timestamp : null Statement Execution Plan Text: Index Row to Base Row ResultSet for FOO: Number of opens = 1 Rows seen = 0 Columns accessed from heap = {1} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 1.00 optimizer estimated cost: 20.96 Index Scan ResultSet for FOO using constraint SQL120126233210150 at serializable isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 0 Rows filtered = 0 Fetch Size = 1 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 scan information: Bit set of columns fetched=All Number of columns fetched=2 Number of deleted rows visited=0 Number of pages visited=2 Number of rows qualified=0 Number of rows visited=0 Scan type=btree Tree height=-1 start position: >= on first 1 column(s). Ordered null semantics on the following columns: 0 stop position: > on first 1 column(s). Ordered null semantics on the following columns: 0 qualifiers: None optimizer estimated row count: 1.00 optimizer estimated cost: 20.96 at org.apache.derbyTesting.functionTests.tests.store.AccessTest.assertStatsOK(AccessTest.java:404) at org.apache.derbyTesting.functionTests.tests.store.AccessTest.doTestCaseCS4595B(AccessTest.java:1715) at org.apache.derbyTesting.functionTests.tests.store.AccessTest.testCS4595B_PrimaryKey(AccessTest.java:1807) 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(Inlined Compiled Code)) at junit.extensions.TestSetup$1.protect(TestSetup.java(Inlined Compiled Code)) at junit.extensions.TestSetup.run(TestSetup.java(Compiled Code)) at junit.extensions.TestDecorator.basicRun(TestDecorator.java(Inlined Compiled Code)) at junit.extensions.TestSetup$1.protect(TestSetup.java(Inlined Compiled Code)) at junit.extensions.TestSetup.run(TestSetup.java(Compiled Code)) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) at junit.extensions.TestDecorator.basicRun(TestDecorator.java(Inlined Compiled Code)) at junit.extensions.TestSetup$1.protect(TestSetup.java(Inlined Compiled Code)) at junit.extensions.TestSetup.run(TestSetup.java(Compiled Code)) FAILURES!!! Tests run: 11966, Failures: 1, Errors: 0
          Hide
          Knut Anders Hatlen added a comment -

          There's not much information about what's gone wrong in the failure report. The attached patch makes assertStatsOK() report the full statistics output on assert failures, which might make it easier to spot what's wrong the next time it happens.

          Committed revision 1227121.

          Show
          Knut Anders Hatlen added a comment - There's not much information about what's gone wrong in the failure report. The attached patch makes assertStatsOK() report the full statistics output on assert failures, which might make it easier to spot what's wrong the next time it happens. Committed revision 1227121.
          Hide
          Dag H. Wanvik added a comment -

          I now saw an AssertionFailedError in testCS4595B_PrimaryKey in the nightlies (also Vista & Java 1.5). May or may not be related:

          http://dbtg.foundry.sun.com/derby/test/Daily/jvm1.5/testing/testlog/vista/1226472-suitesAll_diff.txt

          Stack trace:

          1) testCS4595B_PrimaryKey(org.apache.derbyTesting.functionTests.tests.store.AccessTest)junit.framework.AssertionFailedError
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.assertStatsOK(AccessTest.java:402)
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.doTestCaseCS4595B(AccessTest.java:1708)
          at org.apache.derbyTesting.functionTests.tests.store.AccessTest.testCS4595B_PrimaryKey(AccessTest.java:1800)
          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:116)
          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)
          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)

          Show
          Dag H. Wanvik added a comment - I now saw an AssertionFailedError in testCS4595B_PrimaryKey in the nightlies (also Vista & Java 1.5). May or may not be related: http://dbtg.foundry.sun.com/derby/test/Daily/jvm1.5/testing/testlog/vista/1226472-suitesAll_diff.txt Stack trace: 1) testCS4595B_PrimaryKey(org.apache.derbyTesting.functionTests.tests.store.AccessTest)junit.framework.AssertionFailedError at org.apache.derbyTesting.functionTests.tests.store.AccessTest.assertStatsOK(AccessTest.java:402) at org.apache.derbyTesting.functionTests.tests.store.AccessTest.doTestCaseCS4595B(AccessTest.java:1708) at org.apache.derbyTesting.functionTests.tests.store.AccessTest.testCS4595B_PrimaryKey(AccessTest.java:1800) 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:116) 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) 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)
          Hide
          Kristian Waagan added a comment -

          Looks similar to DERBY-4540.

          Show
          Kristian Waagan added a comment - Looks similar to DERBY-4540 .

            People

            • Assignee:
              Myrna van Lunteren
              Reporter:
              Dag H. Wanvik
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development