Issue Details (XML | Word | Printable)

Key: DERBY-3323
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Minor Minor
Assignee: Kathey Marsden
Reporter: Ole Solberg
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
Derby

ComparisonFailure in derbyStress

Created: 17/Jan/08 10:14 AM   Updated: 29/Jun/09 10:57 PM
Return to search
Component/s: Test
Affects Version/s: 10.4.1.3
Fix Version/s: 10.3.3.0, 10.4.1.3

Time Tracking:
Not Specified

File Attachments:
  Size
Text File Licensed for inclusion in ASF works derby-3323_diff.txt 2008-01-22 01:49 PM Kathey Marsden 2 kB
Environment:
jvm1.4 lin
jvm1.5 lin, linN+1
vm1.6 sles,sol, solN+1
jvm1.5 w2003
Issue Links:
Reference
 

Bug behavior facts: Regression Test Failure
Resolution Date: 04/Feb/08 10:54 PM


 Description  « Hide
See
jvm1.4 lin : http://dbtg.thresher.com/derby/test/Daily/jvm1.4/FailReports/612516_bySig.html
jvm1.5 lin, jvm1.5 linN+1 : http://dbtg.thresher.com/derby/test/Daily/jvm1.5/FailReports/612516_bySig.html
jvm1.6 sles, jvm1.6 sol, jvm1.6 solN+1: http://dbtg.thresher.com/derby/test/Daily/jvm1.6/FailReports/612516_bySig.html
jvm1.5 w2003: http://dbtg.thresher.com/derby/test/10.3Branch/jvm1.5/FailReports/612526_bySig.html

1) derbyStress(org.apache.derbyTesting.functionTests.tests.jdbcapi.JDBCHarnessJavaTest)junit.framework.ComparisonFailure: Output at line 6 expected:<[Test derbyStress finished.]> but was:<[FAIL -- unexpected exception ****************]>
at org.apache.derbyTesting.functionTests.util.CanonTestCase.compareCanon(CanonTestCase.java:100)
at org.apache.derbyTesting.functionTests.util.HarnessJavaTest.runTest(HarnessJavaTest.java:91)
at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:96)
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)
at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)


 All   Comments   Work Log   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
Dag H. Wanvik added a comment - 17/Jan/08 11:40 PM
I saw this in my sandbox too, when stresstest was run as part of the full JUnit regression test (suitesAll).
Rerunning just JDBCHarnessJavaTest saw it pass (Solaris 10/x86, JVM 1.6).

Dag H. Wanvik added a comment - 17/Jan/08 11:59 PM
Duplicate of DERBY-3316? Seems same symptom...

Ole Solberg added a comment - 18/Jan/08 10:02 AM
Agreed, same "signature" as reported by Jørgen.
DERBY-3316 is however marked Closed/Fixed so I'll keep this for the occurences we're still seeing in the nightlies.

Kathey Marsden added a comment - 18/Jan/08 05:38 PM
Ole, do you have the .out file from the failure? I am not able to reproduce and maybe the output will give a clue as to the problem. Also there is an ongoing discussion regarding this test in DERBY-3316 https://issues.apache.org/jira/browse/DERBY-3316?focusedCommentId=12560009#action_12560009

I would like to move the test back to derbyall until it can be properly converted to JUnit with the low memory heap. Unfortunately now it is not testing what it was intended to test because it runs with the heap allocated by the suite jvm. I don't know if such a move would make any difference in the intermittent failure. Dan are you still opposed to the move back to derbyall given my comments in DERBY-3316?

Ole Solberg added a comment - 18/Jan/08 07:37 PM
This is the fail/Embedded_40/JDBCHarnessJavaTest/derbyStress/derbyStress.out:

Test derbyStress starting
Testing with 2000 prepared statements
PASS -- Prepared statement test
DERBY-557: reExecuteStatementTest() PASSED
DERBY-3316: Multiple statement executions
FAIL -- unexpected exception ****************
SQLSTATE(X0X95): Operation 'DROP TABLE' cannot be performed on object 'TAB' because there is an open ResultSet dependent on that object.

from one of todays failures.

I have also copied the full log for this run to http://dbtg.thresher.com/derby/test/debug/612869_sles_suitesAll.zip

Hope this helps.


Kathey Marsden added a comment - 18/Jan/08 09:17 PM
Thanks Ole, that helps alot. The test intentionally does not close ResultSets to test for the leak, but this was causing a problem dropping the table. With revision 613275 I changed the test to close the last ResultSet and force a gc(). Hopefully this will take care of the problem. I will leave the issue open a couple of days to make sure it has gone away. Please post if you see any problem.

Kathey


Daniel John Debrunner added a comment - 18/Jan/08 09:32 PM
> With revision 613275 I changed the test to close the last ResultSet and force a gc().

Adding the forced gc() seems to be a case of making the test pass rather than fixing a potential bug.

Adding a gc() to the test is really saying it's part of the api, and thus this is what applications need to do as well. Since this is not what is required (ie. we don't want to have to say in order to run Derby successfully you need to force gc() once in a while), can we remove the gc() and then fix the bug if the problem remains?

Even closing the ResultSet has the feel of making the test pass rather than fixing a potential bug. Is there a valid explanation for why holding this result set open stops the table being dropped? If there is then it's acceptable to close the result set, but if the ResultSet being open should have no effect on the DROP TABLE then we are merely avoiding seeing a bug by closing the ResultSet.

Kathey Marsden added a comment - 18/Jan/08 09:47 PM
The ResultSets were open and accessing the table and needed to be closed or garbage collected before that reference was eliminated. I did not close the ResultSets as part of the test because I needed to leave them open to test for the leak. It seems reasonable that we were getting the error on drop table if the ResultSets were still referencing the table and not yet garbage collected, so I forced the gc() to allow the table to be dropped. Users would typically need to close all ResultSets referring to a table before the dropped it, I think.




Kathey Marsden added a comment - 21/Jan/08 04:20 PM
I hestitated to port the fix to 10.3 because Dan had some concerns with the fix. He especially did not like the gc, but it seems to me that as long as there are open result sets referring to the table it cannot be dropped. Dan, do you have another recommendation for removing these references so we can drop the table?

Mike Matrigali added a comment - 21/Jan/08 10:52 PM
depending on isolation level and the state of the open results set it would totally be expected that this would stop
a drop from happening. It gets confusing with the various row caches around, but from the bottom up what is expected for read committed:

while a result set is open store will hold a IS table intent lock until the result set is closed. This lock will conflict
with drop table and thus will cause the drop table to block until the result set is closed. It will usually hold one
read committed row lock with is the "current" row in the scan. From store point of view the result set can get closed
in one of 2 ways, either by explicitly closing it or by "nexting" past the last row in the result set. Correlating the second condition is hard from the client side as multiple level of caching (drda and internal "group fetch") make it to tell
the relationship between the "current" row in the application and the actual last row that has been fetched from store.

Daniel John Debrunner added a comment - 21/Jan/08 11:01 PM
Is the System.gc() required? If so we probably need to document this as part of DROP TABLE.

However I think that would be a really bad idea, I thought that Derby itself went through and tried to perform gc() if there were open result sets during such an operation.

Mike Matrigali added a comment - 21/Jan/08 11:02 PM
looking more carefully at the error message I don't think the locking is was is causing the drop error (what I described would likely be the case if the drop and the result sets were in different connections), but instead
probably the dependency manager. My assumption would be that disallowing this ddl is necessary otherwise
one would get strange behavior in the resultset which depends on a stable ddl for the tables in the result set while
the result set is open.

Kathey Marsden added a comment - 22/Jan/08 12:47 AM
We do document:
"The existence of an open cursor that references table being dropped cause the DROP TABLE statement to generate an error, and the table is not dropped."

Which as a user I would read as not closed, either explicitly or by garbage collection. I don't think that it is a bug that DROP TABLE does not attempt garbage collection, but do think it would be a nice improvement. We do so for SET TRANSACTION ISOLATION. Should I file a issue to have Derby attempt garbage collection if it detects open result sets when attempting DROP TABLE?


Daniel John Debrunner added a comment - 22/Jan/08 12:54 AM
I thought DROP TABLE did perform gc since GenericLanguageConnectionContext.verifyNoOpenResultSets does and I thought that's what DROP TABLE would end up calling.

I'm curious, do you know why & where gc() is called for SET TRANSACTION ISOLATION, I can't see the connection ...

Kathey Marsden added a comment - 22/Jan/08 01:10 AM
The gc() happens in GenericLanguageConnectionContext.verifiyAllHeldResultSetsAreClosed() which is called from GenericLanguageConnectionContext.setIsolationLevel(). I missed the gc() in verifyNoOpenResultSets().

Knut Anders Hatlen added a comment - 22/Jan/08 08:57 AM
I don't think we can rely on System.gc() actually freeing and finalizing all unreferenced objects. Its javadoc says that calling the method "suggests that the Java Virtual Machine expend effort toward recycling unused objects" and that it will make a "best effort to reclaim space". Calling it in verifyNoOpenResultSets() as a last attempt before failing is OK, I think, since it increases the likelihood of being able to perform the operation successfully. On the other hand, if a test depends on the side-effects from System.gc() in order to pass, I think it will be inherently unstable (as seen in DERBY-1585).

It's not a bug that DROP TABLE fails, in my opinion, since JDBC only guarantees that a ResultSet releases its resources when it has been closed, and the test code resembles a user error, as it does not close the ResultSets and holds resources for an unnecessarily long period. I'd suggest that the cleanup code instead closes the connection (which ensures that all its database and JDBC resources are released, according to its javadoc), and performs DROP TABLE in a different connection.

Kathey Marsden added a comment - 22/Jan/08 01:49 PM
Attached is a patch which incorporates Knut's suggestion to close the connection to cleanup the result sets. (Thanks Knut!). I hope this is acceptable to all.