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

          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.
          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".
          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 .
          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.
          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.
          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.
          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.
          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.

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development