db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Mamta A. Satoor (Commented) (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (DERBY-5638) intermittent test failure in test_05_ClobNegative when running full largedata._Suite; LobLimitsTestjava.sql.SQLException: Table/View 'BLOBTBL' already exists in Schema 'APP'.
Date Tue, 13 Mar 2012 16:02:41 GMT

    [ https://issues.apache.org/jira/browse/DERBY-5638?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13228473#comment-13228473
] 

Mamta A. Satoor commented on DERBY-5638:
----------------------------------------

I debugged more to see why we get 5 lock timeouts with embedded driver and then 3 locks with
netwrok server before running into intermittent failure. My initial thought was that we will
get 5 lock time outs both with embedded and network server before we give up trying to drop
the tables.

Here is the general flow chart from dropping tables point of view when the suite is using
CleanDatabaseTestSetup. 

At the end of the last test fixture in the suite, CleanDatabaseTestSetup.tearDown gets called
which does following(focusing on drop table related code, ignoring the code related to dropping
aliases, views etc)
CleanDatabaseTestSetup.tearDown->
CleanDatabaseTestSetup.cleanDatabase->
CleanDatabaseTestSetup.removeObjects->
	JDBC.dropSchema->
	....
	// Tables
	rs = dmd.getTables((String) null, schema, (String) null,
                GET_TABLES_TABLE);
		
	dropUsingDMD(s, rs, schema, "TABLE_NAME", "TABLE");
		....
	// At this point there may be tables left due to
        	// foreign key constraints leading to a dependency loop.
	// Drop any constraints that remain and then drop the tables.
	// If there are no tables then this should be a quick no-op.
	.....
	// Tables (again)
        	rs = dmd.getTables((String) null, schema, (String) null,
                	GET_TABLES_TABLE);        
	dropUsingDMD(s, rs, schema, "TABLE_NAME", "TABLE");

The code in dropUsingDMD is as follows
First try to drop the objects in a batch rather than individually.If there is any BatchUpdateException
while dropping the objects as a batch, drop the remaining objects inidividually in a for loop.
If the for loop gets
an exception but some of the objects before the exception got dropped successfully, then go
back into the for loop and try to drop remaining objects again. This continues until either
a)All objects are dropped and we can return
b)no objects can be dropped because of exception

After this CleanDatabaseTestSetup.tearDown is finished(with or without success), the control
goes to the CleanDatabaseTestSetup.setUp for the next suite. Among other things, CleanDatabaseTestSetup.setUp
does following 2 main steps 
1)call CleanDatabaseTestSetup.cleanDatabase (drop any objects in the db)
2)call decorateSQL(create new objects in the db)

Now, let's go through this code in our intermittent failure case. The last test from the embedded
suite LobLimitsTest finishes with no errors and we go to CleanDatabaseTestSetup.tearDown().
This eventually leads to JDBC.dropUsingDMD as shown above. 

In JDBC.dropUsingDMD(), we first try to drop all the tables as a batch rather than individual
drops. Here, we get the first lock timeout. Since we failed here, next we go in a loop to
drop the tables individually. Here we manage to drop "APP"."CLOBTBL2" but get lock time out(2nd
one) for trying to drop "APP"."CLOBTBL". But since the loop was able to drop at least one
table, we go back into the loop to try to drop remaining tables. But that results into 3rd
lock timeout for "APP"."CLOBTBL".  After these tries, the control goes back to JDBC.dropSchema
where we try to drop the tables yet again after dropping any constraints which may be preventing
the table drops(in our case, I don't believe we have any constraints in the db). This 2nd
attempt at dropping the table takes us back to JDBC.dropUsingDMD.Again we try to drop all
the tables as batch but get the 4th lock timeout for "APP"."CLOBTBL". Next, we try to drop
the tables inidividually in a loop, but the drop of "APP"."CLOBTBL" fails with 5th lock timeout.
And since we were not able to drop any table in the loop, we exit out of the loop and eventually
exit out of CleanDatabaseTestSetup.tearDown without reporting all this as a failure even though
we were not able to clean the database of it's objects.

Next, before the beginning of the next suite(which in our case happens to be network server
suite), we go through the CleanDatabaseTestSetup.setUp code. As explained earlier, one of
the things that CleanDatabaseTestSetup.setUp does is to call CleanDatabaseTestSetup.cleanDatabase.
Which again goes through the drop table logic as explained above. It will attempt to drop
the existing tables 
in batch but that runs into 1st lock timeout for "APP"."CLOBTBL". Next, it tries to drop the
table individually, and it runs into 2nd lock timeout. Then the control goes back to CleanDatabaseTestSetup.removeObjects
which calls drop table again after it drops the constraints. This time around, the batch exception
runs into 3rd lock timeout exception. With my understanding of
the code, we should have run into 4th lock timeout trying to drop the table individually but
for some reason, I don't see that 4th lock time out with DRDA driver in derby.log. In any
case, we once again exit 
CleanDatabaseTestSetup.cleanDatabase without successfully getting rid of all the tables and
next step in CleanDatabaseTestSetup.setUp is the call to decorateSQL().decorateSQL fails when
it tries to create tables but they already exist in the database becaue CleanDatabaseTestSetup.cleanDatabase
was not able to get rid of them and that is why we get the exception Table/View 'BLOBTBL'
already exists in Schema 'APP'.

I am not sure why this locking issue is only intermittent but atleast we understand what is
happening during the suite runs.

Not sure if it is correct for CleanDatabaseTestSetup.cleanDatabase to run into exceptions
while doing the cleanup but ignore those exceptions. I ran into a very old jira DERBY-2220(Uncommitted
transactions executed throught XAResource will held locks after the application terminates
(or crashes during the transaction).) where there was a brief conversation about how may be
CleanDatabaseTestSetup.cleanDatabase should drop the database if it is not able to drop the
objects inside the database. Here is part of Dan Debrunner's comment on that issue
******************
I also think that you've found an issue in the clean database decorator and as 
such it would be good to fix it centrally there, rather than in a single test. 
for example, if the clean database decorator failed to cleanup the database, 
it could report the failure and then blow away the database.
******************

We can do atleast one of the two things for this particular jira at this point (or may be
even both)
1)Have CleanDatabaseTestSetup.cleanDatabase report that it is having trouble deleting the
objects and hence it will drop the database and create the objects mentioned in decorateSQL.
This will get rid of intermittent failures in large data suite but it will not explain why
do we intermittently run into lock timeouts
2)Debug why we are running into intermittently lock timeouts with large data suite. I am running
the tests with derby.locks.deadlockTrace=true to see if it will give us more information about
the locks.

Please let me know if there are any other options we could be pursuing.
                
> intermittent test failure in test_05_ClobNegative when running full largedata._Suite;
LobLimitsTestjava.sql.SQLException: Table/View 'BLOBTBL' already exists in Schema 'APP'.
> ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
>                 Key: DERBY-5638
>                 URL: https://issues.apache.org/jira/browse/DERBY-5638
>             Project: Derby
>          Issue Type: Bug
>          Components: Test
>    Affects Versions: 10.9.0.0
>         Environment: ibm 1.6 sr9 fp1, Seen on Windows XP/VMWare, and Linux (CentOS)/VMWare
>            Reporter: Myrna van Lunteren
>            Assignee: Mamta A. Satoor
>         Attachments: CompleteRunallWithPrintlnTrace.out, DERBY5638_patch1_diff.txt, DERBY5638_patch2_diff.txt,
derbyFailed.log, derbyPass.log, derbyWithRollbackInTest_05.log, derbyallFailWithPrintlnTrace.log,
runallForSuccessfulLargeDataRun.out, runallWithPrintlnTrace.out
>
>
> I've seen the following failure when running the largedata suite:
> (emb)largedata.Derby5624Test.testDERBY_5624 used 518403 ms .
> (emb)largedata.LobLimitsTest.test_01_Blob used 2422 ms .
> (emb)largedata.LobLimitsTest.test_02_BlobNegative used 31 ms .
> (emb)largedata.LobLimitsTest.test_03_Clob1 used 2375 ms .
> (emb)largedata.LobLimitsTest.test_04_Clob2 used 3234 ms .
> (emb)largedata.LobLimitsTest.test_05_ClobNegative used 516 ms .
> (net)largedata.LobLimitsTest.test_01_Blob used 5360 ms .
> (net)largedata.LobLimitsTest.test_02_BlobNegative used 32 ms .
> (net)largedata.LobLimitsTest.test_03_Clob1 used 2078 ms .
> (net)largedata.LobLimitsTest.test_04_Clob2 used 2390 ms .
> (net)largedata.LobLimitsTest.test_05_ClobNegative used 938 ms .
> (emb)largedata.LobLimitsTest.test_01_Blob used 9188238 ms .
> (emb)largedata.LobLimitsTest.test_02_BlobNegative used 109 ms .
> (emb)largedata.LobLimitsTest.test_03_Clob1 used 8116714 ms .
> (emb)largedata.LobLimitsTest.test_04_Clob2 used 2164002 ms .
> (emb)largedata.LobLimitsTest.test_05_ClobNegative used 685745 ms E
> Time: 22,320.138
> There was 1 error:
> 1) LobLimitsTestjava.sql.SQLException: Table/View 'BLOBTBL' already exists in Schema
'APP'.
> 	at org.apache.derby.client.am.SQLExceptionFactory40.getSQLException(Unknown Source)
> 	at org.apache.derby.client.am.SqlException.getSQLException(Unknown Source)
> 	at org.apache.derby.client.am.Statement.execute(Unknown Source)
> 	at org.apache.derbyTesting.functionTests.tests.largedata.LobLimitsTest.setupTables(LobLimitsTest.java:107)
> 	at org.apache.derbyTesting.functionTests.tests.largedata.LobLimitsTest$1.decorateSQL(LobLimitsTest.java:141)
> 	at org.apache.derbyTesting.junit.CleanDatabaseTestSetup.setUp(CleanDatabaseTestSetup.java:112)
> 	at junit.extensions.TestSetup$1.protect(TestSetup.java:20)
> 	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)
> 	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)
> Caused by: org.apache.derby.client.am.SqlException: Table/View 'BLOBTBL' already exists
in Schema 'APP'.
> 	at org.apache.derby.client.am.Statement.completeSqlca(Unknown Source)
> 	at org.apache.derby.client.am.Statement.completeExecuteImmediate(Unknown Source)
> 	at org.apache.derby.client.net.NetStatementReply.parseEXCSQLIMMreply(Unknown Source)
> 	at org.apache.derby.client.net.NetStatementReply.readExecuteImmediate(Unknown Source)
> 	at org.apache.derby.client.net.StatementReply.readExecuteImmediate(Unknown Source)
> 	at org.apache.derby.client.net.NetStatement.readExecuteImmediate_(Unknown Source)
> 	at org.apache.derby.client.am.Statement.readExecuteImmediate(Unknown Source)
> 	at org.apache.derby.client.am.Statement.flowExecute(Unknown Source)
> 	at org.apache.derby.client.am.Statement.executeX(Unknown Source)
> 	... 26 more
> Unfortunately, when this happens, there seems to be no 'fail' directory created. The
derby.log in the system directory looks very innocent (just some start up and shutting down
of the database), and the serverConsoleOutput.log only has the typical 'failed to find db
'wombat' messages'.
> Note, when this happens, the suite exits, so that instead of the expected 20 (or 21 on
windows, see DERBY-5624 for reason for skipping on Linux default installs with 1024 max open
files) we only get 15 (or 16) tests run - if the test doesn't fail it goes on to run the last
5 fixtures again for network server.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

       

Mime
View raw message