db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Bryan Pendleton (JIRA)" <j...@apache.org>
Subject [jira] Updated: (DERBY-4297) 'compilation time did not compute (0,0,0,0) expected:<16> but was:<0>' in testGroupBySortProps(....tests.lang.XplainStatisticsTest)
Date Fri, 04 Dec 2009 17:06:20 GMT

     [ https://issues.apache.org/jira/browse/DERBY-4297?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Bryan Pendleton updated DERBY-4297:
-----------------------------------

    Assignee: Bryan Pendleton

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.

> 'compilation time did not compute (0,0,0,0) expected:<16> but was:<0>' in
testGroupBySortProps(....tests.lang.XplainStatisticsTest)
> -----------------------------------------------------------------------------------------------------------------------------------
>
>                 Key: DERBY-4297
>                 URL: https://issues.apache.org/jira/browse/DERBY-4297
>             Project: Derby
>          Issue Type: Bug
>          Components: SQL, Test
>    Affects Versions: 10.6.0.0
>         Environment: OS:
> Microsoft Windows XP Professional - 5.1.2600 Service Pack 3 Build 2600
> CYGWIN_NT-5.1 1.5.25(0.156/4/2) 2008-06-12 19:34 Cygwin
> JVM:
> Sun Microsystems Inc.
> java version "1.5.0_16"
> Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_16-b02)
> Java HotSpot(TM) Client VM (build 1.5.0_16-b02, mixed mode, sharing)
>            Reporter: Ole Solberg
>            Assignee: Bryan Pendleton
>            Priority: Minor
>
> 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)

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


Mime
View raw message