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 Fri, 09 Mar 2012 20:10:59 GMT

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

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

Mike commented "And to me it looks like the intermittent error happens while setting up to
run test_05_ClobNegative. But your fix seems to be to change logic at the end of test_05_ClobNegative.
"

My understanding of CleanDatabaseTestSetup is that it runs the steup at the beginning of the
suite run and it runs the teardown at the end of the suite after the last test has run. And
these same steps repeat for every suite. I have put couple printlns in CleanDatabaseTestSetup
to see this sequence while running large data suite. To see these printlns, we need to pass
derby.tests.trace=true as shown below
$ time java -Dderby.tests.debug=true -Dderby.tests.trace=true junit.textui.TestRunner org.apache.derbyTesting.functionTests.tests.largedata._Suite
> runall.out 2>&1
The use of Dderby.tests.trace=true puts all the println to the console(which I have redirected
to runall.out in my case)

The tests have not finished running(I will attach runall.out with what I have so far. It is
very verbose because all the existing printlns will now get printed because of trace flag.
You can search for "DEBUG: cleanDatabase" in that file to see when setup and teardown gets
called). I can see that debug println for setup happens before the suite is run. Then after
the suite is finished, teardown is run before the new suite is started. And so on and so forth.

eg of such a sequence (largedata.Derby5624Test.testDERBY_5624  is the first suite and it has
just one fixture. largedata.LobLimitsTest.test_01_Blob is start of a new suite.)

DEBUG: cleanDatabase start in setup
DEBUG: cleanDatabase end in setup
.
(emb)largedata.Derby5624Test.testDERBY_5624 used 299858 ms DEBUG: cleanDatabase start in teardown
DEBUG: cleanDatabase end in teardown
DEBUG: cleanDatabase start in setup
DEBUG: cleanDatabase end in setup
DEBUG: BIGGEST_LOB_SZ=1048576 BIG_LOB_SZ=102400
.
(emb)largedata.LobLimitsTest.test_01_Blob DEBUG: ========================================


An interesting eg of the setup and teardown can be seen when the last test in embedded suite
has run and when the next suite is getting run in network server(largedata.LobLimitsTest.test_05_ClobNegative
is the last test in the previous suite. largedata.LobLimitsTest.test_01_Blob is the first
fixture for next suite which is a network server suite)
(emb)largedata.LobLimitsTest.test_05_ClobNegative DEBUG: at the beginning of test_05_ClobNegative
DEBUG: ========================================
DEBUG: START ClobTest #7insert Clob of size = 102400
DEBUG: Got reader for file extinout/charLobLimits.txt java.io.FileReader@38203820
DEBUG: Closed reader for file extinout/charLobLimits.txt java.io.FileReader@38203820
DEBUG: ========================================
DEBUG: START ClobTest #7insert Clob of size = 102400
DEBUG: Got reader for file extinout/charLobLimits.txt java.io.FileReader@46034603
DEBUG: Closed reader for file extinout/charLobLimits.txt java.io.FileReader@46034603
DEBUG: Got FileWriter for extinout/charLobLimits.txt java.io.FileWriter@34243424
DEBUG: writer java.io.FileWriter@34243424 for file extinout/charLobLimits.txt closed
DEBUG: ========================================
DEBUG: START ClobTest #9.1 insert Clob of size = 102401
DEBUG: Got reader for file extinout/charLobLimits.txt java.io.FileReader@5e015e01
DEBUG: Closed reader for file extinout/charLobLimits.txt java.io.FileReader@5e015e01
DEBUG: ========================================
DEBUG: START ClobTest #9.2  - SELECT CLOB of size = 102400
DEBUG: Matched rows selected with clob of size(102400) =0
DEBUG: Select Clob (102400) rows= 0 = 7
DEBUG: ========================================
DEBUG: ========================================
DEBUG: START ClobTest #10 insert Clob of size = 102401
DEBUG: Got reader for file extinout/charLobLimits.txt java.io.FileReader@35f135f1
DEBUG: Closed reader for file extinout/charLobLimits.txt java.io.FileReader@35f135f1
DEBUG: ========================================
DEBUG: START ClobTest #11 insert Clob of size = 102401
DEBUG: Got reader for file extinout/charLobLimits.txt java.io.FileReader@77f277f2
DEBUG: Closed reader for file extinout/charLobLimits.txt java.io.FileReader@77f277f2
DEBUG: Rows deleted =2
DEBUG: ========================================
DEBUG: START ClobTest #12.1  -insertClob of size = 102400
DEBUG: ========================================
DEBUG: START ClobTest #12.2 - SELECT CLOB of size = 102400
DEBUG: Select Clob (102400) rows= 0 = 1
DEBUG: Matched rows selected with clob of size(102400) =0
DEBUG: ========================================
DEBUG: Rows deleted =2
DEBUG: ========================================
DEBUG: START ClobTest #13 (setClob with 4Gb clobinsertClob of size = 4294967296
DEBUG: at the end of test_05_ClobNegative
used 506 ms DEBUG: cleanDatabase start in teardown
DEBUG: cleanDatabase end in teardown
DEBUG: Starting network server:
DEBUG: cleanDatabase start in setup
DEBUG: cleanDatabase end in setup
DEBUG: BIGGEST_LOB_SZ=1048576 BIG_LOB_SZ=102400
.
(net)largedata.LobLimitsTest.test_01_Blob DEBUG: ========================================

So based on the above information, I believe that the intermittent error happens after the
last test  test_05_ClobNegative in the embedded suite has finished running and while in the
teardown code, it keeps running into lock time out exceptions(the drop objects is tried 5
times and we see 5 lock timeouts). Then the network server is started, it goes through the
setup method. The setup method in CleanDatabaseTestSetup looks as follows
    protected void setUp() throws Exception {
        if (jdbcClient != null )
        { // We have network client (useNetworkClient) on a given host and port.
            TestConfiguration current = TestConfiguration.getCurrent();
            TestConfiguration modified = new TestConfiguration(current, 
                    jdbcClient,
                    hostName, 
                    portNo);
            TestConfiguration.setCurrent(modified);
        }
        Connection conn = getConnection();
        conn.setAutoCommit(false);
        
        // compress as well to allow the fixtures wrapped in
        // this decorator to start with a clean database.
      	println("cleanDatabase start in setup");
        CleanDatabaseTestSetup.cleanDatabase(conn, true);  
      	println("cleanDatabase end in setup");
        
        Statement s = conn.createStatement();
        decorateSQL(s);

        s.close();
        conn.commit();
        conn.close();
    }

setup() first does the drop of objects again and then goes through the decorateSQL to create
test obects again. This is where in failed intermittent failures, I believe we start seeing
more lock time outs for drop table but with network server driver(because the new suite is
network server suite). And subsequent try to create the table fails because we were never
able to drop the tables successfully because of lock timeouts.

Sorry for this being such a long comment. Please ask me questions if this is not clear. I
will post svn diff for simple printlns I put for tracking when setup and teardowns are getting
called. I will also put the runall.out for what has finished so far with these extra printlns.
                
> 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: DERBY5638_patch1_diff.txt, derbyFailed.log, derbyPass.log, derbyWithRollbackInTest_05.log
>
>
> 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