Derby
  1. Derby
  2. DERBY-6144

nightly regression test failure, intermittent error : testStatisticsCorrectness(org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStatisticsTest)junit.framework.AssertionFailedError

    Details

    • Bug behavior facts:
      Regression, Regression Test Failure

      Description

      failure in nightly regression test, candidate 10.10 branch, ibm17

      may be related to daylight savings time change, there were similar resolved bugs that were marked fixed,
      so reporting new one in case this is different.

      http://people.apache.org/~myrnavl/derby_test_results/v10_10/windows/testlog/ibm17/1461391-suites.All_diff.txt

      There was 1 failure:
      1) testStatisticsCorrectness(org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStatisticsTest)junit.framework.AssertionFailedError
      at org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStatisticsTest.testStatisticsCorrectness(AutomaticIndexStatisticsTest.java:332)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
      at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:117)
      at org.apache.derbyTesting.junit.BaseJDBCTestCase.runBareOverridable(BaseJDBCTestCase.java:424)
      at org.apache.derbyTesting.junit.BaseJDBCTestCase.runBare(BaseJDBCTestCase.java:441)
      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)
      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)

        Issue Links

          Activity

          Mike Matrigali created issue -
          Hide
          Mike Matrigali added a comment -

          have not seen this in a previous release, marking it a regression.

          Show
          Mike Matrigali added a comment - have not seen this in a previous release, marking it a regression.
          Mike Matrigali made changes -
          Field Original Value New Value
          Bug behavior facts Regression Test Failure [ 10369 ] Regression,Regression Test Failure [ 10420, 10369 ]
          Hide
          Mike Matrigali added a comment -

          The following assert failed at line 332:
          assertTrue(s.created.before(now));

          A snippet of the test:
          // Select to trigger statistics generation.
          forceRowCountEstimateUpdate(TAB);
          JDBC.assertDrainResults(
          prepareStatement("select * from " + TAB + " where id1 = 10")
          .executeQuery());

          // We expect three stats objects for the single index; one per
          // leading columns combination (c1, c1-c2, and c1-c2-c3).
          IdxStats statsObj[] = stats.getStatsTable(TAB, 3);
          assertEquals(3, statsObj.length);

          Timestamp now = new Timestamp(new Date().getTime());
          for (int i=0; i < statsObj.length; i++) {
          IdxStats s = statsObj[i];
          assertEquals(rows, s.rows);
          assertTrue(s.created.before(now));
          switch (s.lcols)

          { case 1: assertEquals(100, s.card); break; case 2: assertEquals(5000, s.card); break; case 3: assertEquals(50000, s.card); break; default: fail("unexpected number of leading columns: " + s.lcols); }

          }

          Timestamp now = new Timestamp(new Date().getTime());

          It failed sometime friday 4/5 night or 4/6 morning. I think this means it is not a daylight savings time issue.

          I think what is being tested is that background stat is creating stats and that those stats were created before "now". I have
          sometimes seen harware dependent issues with this kind of thing and stuff going so fast that maybe the time they were
          created and now are the same value.

          I am running 100 times to see if I can reproduce but so far no luck, and considering at least changing the test to print the interesting bits on failure,
          and possibly adding a sleep before getting "now" to make sure clock time elapses between stat creation and "now".

          Show
          Mike Matrigali added a comment - The following assert failed at line 332: assertTrue(s.created.before(now)); A snippet of the test: // Select to trigger statistics generation. forceRowCountEstimateUpdate(TAB); JDBC.assertDrainResults( prepareStatement("select * from " + TAB + " where id1 = 10") .executeQuery()); // We expect three stats objects for the single index; one per // leading columns combination (c1, c1-c2, and c1-c2-c3). IdxStats statsObj[] = stats.getStatsTable(TAB, 3); assertEquals(3, statsObj.length); Timestamp now = new Timestamp(new Date().getTime()); for (int i=0; i < statsObj.length; i++) { IdxStats s = statsObj [i] ; assertEquals(rows, s.rows); assertTrue(s.created.before(now)); switch (s.lcols) { case 1: assertEquals(100, s.card); break; case 2: assertEquals(5000, s.card); break; case 3: assertEquals(50000, s.card); break; default: fail("unexpected number of leading columns: " + s.lcols); } } Timestamp now = new Timestamp(new Date().getTime()); It failed sometime friday 4/5 night or 4/6 morning. I think this means it is not a daylight savings time issue. I think what is being tested is that background stat is creating stats and that those stats were created before "now". I have sometimes seen harware dependent issues with this kind of thing and stuff going so fast that maybe the time they were created and now are the same value. I am running 100 times to see if I can reproduce but so far no luck, and considering at least changing the test to print the interesting bits on failure, and possibly adding a sleep before getting "now" to make sure clock time elapses between stat creation and "now".
          Mike Matrigali made changes -
          Link This issue is related too DERBY-5046 [ DERBY-5046 ]
          Hide
          Mike Matrigali added a comment -

          looks like DERBY-6144 is another part of the test that needs same fix as DERBY-5046.

          Show
          Mike Matrigali added a comment - looks like DERBY-6144 is another part of the test that needs same fix as DERBY-5046 .
          Mike Matrigali made changes -
          Assignee Mike Matrigali [ mikem ]
          Hide
          Mike Matrigali added a comment -

          will just change test in all places to allow for same timestamp like in DERBY-5046.

          Show
          Mike Matrigali added a comment - will just change test in all places to allow for same timestamp like in DERBY-5046 .
          Hide
          Mike Matrigali added a comment -

          checked in fix to trunk:
          ------------------------------------------------------------------------
          r1467011 | mikem | 2013-04-11 10:58:55 -0700 (Thu, 11 Apr 2013) | 9 lines

          DERBY-6144 nightly regression test failure, intermittent error : testStatisticsCorrectness(org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStatisticsTest)junit.framework.A

          test was asserting that stats had to be created after "now". I think the
          nightly was getting a case where the time was the same. DERBY-5046 fixed
          a different part to the same test to check for greater than now, so implemented
          that same fix at the offending line. Also added some text to be printed with
          the variable values if it happens again.

          Show
          Mike Matrigali added a comment - checked in fix to trunk: ------------------------------------------------------------------------ r1467011 | mikem | 2013-04-11 10:58:55 -0700 (Thu, 11 Apr 2013) | 9 lines DERBY-6144 nightly regression test failure, intermittent error : testStatisticsCorrectness(org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStatisticsTest)junit.framework.A test was asserting that stats had to be created after "now". I think the nightly was getting a case where the time was the same. DERBY-5046 fixed a different part to the same test to check for greater than now, so implemented that same fix at the offending line. Also added some text to be printed with the variable values if it happens again.
          Mike Matrigali made changes -
          Fix Version/s 10.11.0.0 [ 12324243 ]
          Hide
          Mamta A. Satoor added a comment - - edited

          Test failed on 10.10(1465320) with ibm 16 (Mike has put in a fix though, so this should not be an issue anymore)
          testStatisticsCorrectness(org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStatisticsTest)junit.framework.AssertionFailedError
          at org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStatisticsTest.testStatisticsCorrectness(AutomaticIndexStatisticsTest.java:332)
          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:117)
          at org.apache.derbyTesting.junit.BaseJDBCTestCase.runBareOverridable(BaseJDBCTestCase.java:442)
          at org.apache.derbyTesting.junit.BaseJDBCTestCase.runBare(BaseJDBCTestCase.java:459)
          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)
          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
          Mamta A. Satoor added a comment - - edited Test failed on 10.10(1465320) with ibm 16 (Mike has put in a fix though, so this should not be an issue anymore) testStatisticsCorrectness(org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStatisticsTest)junit.framework.AssertionFailedError at org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStatisticsTest.testStatisticsCorrectness(AutomaticIndexStatisticsTest.java:332) 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:117) at org.apache.derbyTesting.junit.BaseJDBCTestCase.runBareOverridable(BaseJDBCTestCase.java:442) at org.apache.derbyTesting.junit.BaseJDBCTestCase.runBare(BaseJDBCTestCase.java:459) 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) 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)
          Hide
          Mike Matrigali added a comment -

          backported chage #1467011 fix from trunk to 10.10 branch
          s10_10_ibm17:7>svn commit
          Sending .
          Sending java\testing\org\apache\derbyTesting\functionTests\tests\store\AutomaticIndexStatisticsTest.java
          Transmitting file data .
          Committed revision 1467128.

          Show
          Mike Matrigali added a comment - backported chage #1467011 fix from trunk to 10.10 branch s10_10_ibm17:7>svn commit Sending . Sending java\testing\org\apache\derbyTesting\functionTests\tests\store\AutomaticIndexStatisticsTest.java Transmitting file data . Committed revision 1467128.
          Mike Matrigali made changes -
          Fix Version/s 10.10.1.2 [ 12324247 ]
          Hide
          Mike Matrigali added a comment -

          back ported fix from trunk to 10.9 branch.
          s10_9_ibm17:10>svn commit
          Sending .
          Sending java\testing\org\apache\derbyTesting\functionTests\tests\store\AutomaticIndexStatisticsTest.java
          Transmitting file data .
          Committed revision 1467132.

          Show
          Mike Matrigali added a comment - back ported fix from trunk to 10.9 branch. s10_9_ibm17:10>svn commit Sending . Sending java\testing\org\apache\derbyTesting\functionTests\tests\store\AutomaticIndexStatisticsTest.java Transmitting file data . Committed revision 1467132.
          Mike Matrigali made changes -
          Fix Version/s 10.9.2.2 [ 12324102 ]
          Hide
          Mike Matrigali added a comment -

          backported fix from trunk to 10.8 branch:

          s10_8_ibm16:15>svn commit
          Sending .
          Sending java\testing\org\apache\derbyTesting\functionTests\tests\store\AutomaticIndexStatisticsTest.java
          Transmitting file data .
          Committed revision 1467136.

          This test was created for a new feature in 10.8, so this change need not be backported to any version before 10.8, addied the backport reject label.

          Show
          Mike Matrigali added a comment - backported fix from trunk to 10.8 branch: s10_8_ibm16:15>svn commit Sending . Sending java\testing\org\apache\derbyTesting\functionTests\tests\store\AutomaticIndexStatisticsTest.java Transmitting file data . Committed revision 1467136. This test was created for a new feature in 10.8, so this change need not be backported to any version before 10.8, addied the backport reject label.
          Mike Matrigali made changes -
          Labels derby_backport_reject_10_7
          Fix Version/s 10.8.3.1 [ 12323475 ]
          Hide
          Mike Matrigali added a comment -

          Marking this fixed. If it shows up again in nightly's after this fix, just reopen the bug.

          Show
          Mike Matrigali added a comment - Marking this fixed. If it shows up again in nightly's after this fix, just reopen the bug.
          Mike Matrigali made changes -
          Status Open [ 1 ] Resolved [ 5 ]
          Resolution Fixed [ 1 ]
          Rick Hillegas made changes -
          Fix Version/s 10.9.1.1 [ 12323562 ]
          Fix Version/s 10.9.2.2 [ 12324102 ]
          Gavin made changes -
          Link This issue is related to DERBY-5046 [ DERBY-5046 ]
          Gavin made changes -
          Link This issue is related to DERBY-5046 [ DERBY-5046 ]
          Mike Matrigali made changes -
          Status Resolved [ 5 ] Closed [ 6 ]
          Gavin made changes -
          Workflow jira [ 12774834 ] Default workflow, editable Closed status [ 12796949 ]
          Myrna van Lunteren made changes -
          Affects Version/s 10.10.2.0 [ 12326659 ]
          Affects Version/s 10.10.1.4 [ 12324247 ]
          Fix Version/s 10.10.2.0 [ 12326659 ]
          Fix Version/s 10.10.1.4 [ 12324247 ]
          Transition Time In Source Status Execution Times Last Executer Last Execution Date
          Open Open Resolved Resolved
          8d 22h 2m 1 Mike Matrigali 12/Apr/13 00:21
          Resolved Resolved Closed Closed
          68d 17h 55m 1 Mike Matrigali 19/Jun/13 18:16

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development