Derby
  1. Derby
  2. DERBY-4297

'compilation time did not compute (0,0,0,0) expected:<16> but was:<0>' in testGroupBySortProps(....tests.lang.XplainStatisticsTest)

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 10.6.1.0
    • Fix Version/s: 10.6.1.0
    • Component/s: SQL, Test
    • Labels:
      None
    • Environment:
    • Urgency:
      Normal
    • Bug behavior facts:
      Regression Test Failure

      Description

      Seen in
      http://dbtg.thresher.com/derby/test/trunk15/jvm1.5/testing/testlog/CYGWIN_NT-5.1_i686-unknown/790694-org.apache.derbyTesting.functionTests.suites.All_diff.txt

      There was 1 failure:
      1) testGroupBySortProps(org.apache.derbyTesting.functionTests.tests.lang.XplainStatisticsTest)junit.framework.AssertionFailedError: compilation time did not compute (0,0,0,0) expected:<16> but was:<0>
      at org.apache.derbyTesting.functionTests.tests.lang.XplainStatisticsTest.verifySensibleStatementTimings(XplainStatisticsTest.java:707)
      at org.apache.derbyTesting.functionTests.tests.lang.XplainStatisticsTest.testGroupBySortProps(XplainStatisticsTest.java:1011)
      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:22)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
      at junit.extensions.TestSetup.run(TestSetup.java:23)
      at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)

      1. d4297-unused.diff
        0.6 kB
        Knut Anders Hatlen

        Activity

        Ole Solberg created issue -
        Hide
        Bryan Pendleton added a comment -

        Hi Ole, I just noticed this, sorry I didn't pay attention to it before.

        Does this happen routinely? Or did it happen only once?

        The values "16" and "0" are interesting because on Windows,
        System.currentTimeMillis returns values from the 60 Hz timer
        which means that the values often appear to advance in "jumps"
        of 16 (sometimes 15).

        This might be a problem in the test, which is a relatively new test,
        or it might indicate a weakness in the compile_time measurement
        logic in the compilation code.

        Show
        Bryan Pendleton added a comment - Hi Ole, I just noticed this, sorry I didn't pay attention to it before. Does this happen routinely? Or did it happen only once? The values "16" and "0" are interesting because on Windows, System.currentTimeMillis returns values from the 60 Hz timer which means that the values often appear to advance in "jumps" of 16 (sometimes 15). This might be a problem in the test, which is a relatively new test, or it might indicate a weakness in the compile_time measurement logic in the compilation code.
        Hide
        Ole Solberg added a comment -

        Hi Brian,

        I see 9 occurences of this signature since ~2009-07-30

        See http://dbtg.foundry.sun.com/derby/test/stats_newest.html and the entry for 4297.

        Show
        Ole Solberg added a comment - Hi Brian, I see 9 occurences of this signature since ~2009-07-30 See http://dbtg.foundry.sun.com/derby/test/stats_newest.html and the entry for 4297.
        Hide
        Bryan Pendleton added a comment -

        I think that this may be due to the way that 'compileTime' is computed
        in GenericStatement.prepMinion(). During the processing of the statement,
        GenericStatement computes the overall time that was taken, and breaks
        it down into various phases: parse time, bind time, optimize time, generate time,
        and overall compileTime. It does this by calling System.currentTimeMillis() at
        various points, and recording the value.

        However, I think there is a hole in the current algorithm in which, if the
        System.currentTimeMillis clock "ticks" after the line

        generateTime = getCurrentTimeMillis(lcc); (line 471)

        and before the line

        preparedStmt.setCompileTimeMillis(...) (line 521)

        then we can have a result where compileTime != (parseTime+bindTime+optimizeTime+generateTime),
        which is the invariant being tested by the test.

        I think that we may be able to fix this with the following change (not yet tested):

        Index: GenericStatement.java
        ===================================================================
        — GenericStatement.java (revision 884222)
        +++ GenericStatement.java (working copy)
        @@ -521,7 +521,7 @@
        bindTime - parseTime, //bind time
        optimizeTime - bindTime, //optimize time
        generateTime - optimizeTime, //generate time

        • getElapsedTimeMillis(beginTime),
          + generateTime - beginTime,//compile time
          beginTimestamp,
          endTimestamp);
          }

        I'm not sure how important or useful these times are, nowadays; modern
        processors are so fast, and System.currentTimeMillis is so slow, then
        in general the times are always (0,0,0,0).

        But I'll experiment with this change, and if it doesn't seem to do any harm,
        we can see if it makes this test more reliable.

        Show
        Bryan Pendleton added a comment - I think that this may be due to the way that 'compileTime' is computed in GenericStatement.prepMinion(). During the processing of the statement, GenericStatement computes the overall time that was taken, and breaks it down into various phases: parse time, bind time, optimize time, generate time, and overall compileTime. It does this by calling System.currentTimeMillis() at various points, and recording the value. However, I think there is a hole in the current algorithm in which, if the System.currentTimeMillis clock "ticks" after the line generateTime = getCurrentTimeMillis(lcc); (line 471) and before the line preparedStmt.setCompileTimeMillis(...) (line 521) then we can have a result where compileTime != (parseTime+bindTime+optimizeTime+generateTime), which is the invariant being tested by the test. I think that we may be able to fix this with the following change (not yet tested): Index: GenericStatement.java =================================================================== — GenericStatement.java (revision 884222) +++ GenericStatement.java (working copy) @@ -521,7 +521,7 @@ bindTime - parseTime, //bind time optimizeTime - bindTime, //optimize time generateTime - optimizeTime, //generate time getElapsedTimeMillis(beginTime), + generateTime - beginTime,//compile time beginTimestamp, endTimestamp); } I'm not sure how important or useful these times are, nowadays; modern processors are so fast, and System.currentTimeMillis is so slow, then in general the times are always (0,0,0,0). But I'll experiment with this change, and if it doesn't seem to do any harm, we can see if it makes this test more reliable.
        Bryan Pendleton made changes -
        Field Original Value New Value
        Assignee Bryan Pendleton [ bryanpendleton ]
        Hide
        Knut Anders Hatlen added a comment -

        > I'm not sure how important or useful these times are, nowadays; modern
        > processors are so fast, and System.currentTimeMillis is so slow, then
        > in general the times are always (0,0,0,0).

        Would it make sense to change the unit to nanoseconds and use
        System.nanoTime() on the platforms that support it?

        Show
        Knut Anders Hatlen added a comment - > I'm not sure how important or useful these times are, nowadays; modern > processors are so fast, and System.currentTimeMillis is so slow, then > in general the times are always (0,0,0,0). Would it make sense to change the unit to nanoseconds and use System.nanoTime() on the platforms that support it?
        Hide
        Bryan Pendleton added a comment -

        My regression test run was clean so I decided to commit this fix so we can
        see if it improves the behavior of the test or not.

        Knut, thanks for the suggestion about nanoTime. I filed DERBY-4462 to track that idea.

        Show
        Bryan Pendleton added a comment - My regression test run was clean so I decided to commit this fix so we can see if it improves the behavior of the test or not. Knut, thanks for the suggestion about nanoTime. I filed DERBY-4462 to track that idea.
        Bryan Pendleton made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Fix Version/s 10.6.0.0 [ 12313727 ]
        Resolution Fixed [ 1 ]
        Hide
        Knut Anders Hatlen added a comment -

        I believe that GenericStatement.getElapsedTimeMillis() is unused after the changes in this issue. The attached patch removes the method. I've started the regression tests to verify that it's no longer needed.

        Show
        Knut Anders Hatlen added a comment - I believe that GenericStatement.getElapsedTimeMillis() is unused after the changes in this issue. The attached patch removes the method. I've started the regression tests to verify that it's no longer needed.
        Knut Anders Hatlen made changes -
        Attachment d4297-unused.diff [ 12427935 ]
        Hide
        Knut Anders Hatlen added a comment -

        The regression tests passed with the method removed.
        Committed revision 890448.

        Show
        Knut Anders Hatlen added a comment - The regression tests passed with the method removed. Committed revision 890448.
        Kathey Marsden made changes -
        Status Resolved [ 5 ] Closed [ 6 ]
        Gavin made changes -
        Workflow jira [ 12467457 ] Default workflow, editable Closed status [ 12799726 ]

          People

          • Assignee:
            Bryan Pendleton
            Reporter:
            Ole Solberg
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development