jdbcapi/SetQueryTimeoutTest.java fails on IBM wctme 5.7

• Key: DERBY-1848
• Type: Bug
• Status: Resolved
• Resolution: Fixed
• Priority: Major
• Assignee: Mamta A. Satoor
• Reporter: Rajesh Kartha
• Component/s: Test
• Affects Version/s: 10.2.2.1, 10.3.1.4, 10.5.1.1
• Fix Version/s: 10.4.2.0, 10.5.1.1

Description

The following is the diff:

*** Start: SetQueryTimeoutTest jdk1.3.1 subset - 2.2 derbyall:jdbcapi 2006-09-10 11:07:05 ***
7 del
< Statement 1 completed
8 del
< Statement 2 completed
9 del
< Statement 3 completed
10 del
< Testing timeout with an execute operation
11 del
< Statements that should time out timed out, and statements that should complete completed
12 del
< Testing setting a negative timeout value
13 del
< Negative timeout value caused exception, as expected
14 del
< Execute returned a ResultSet
15 del
< Testing that Statement remembers timeout.
16 del
< Testing that PreparedStatement remembers timeout.
17 del
< Testing that CallableStatement remembers timeout.
18 del
< Testing timeout with executeUpdate call.
19 del
< Test SetQueryTimeoutTest PASSED
19a7,11
> Test SetQueryTimeoutTest FAILED
> org.apache.derbyTesting.functionTests.tests.jdbcapi.SetQueryTimeoutTest$TestFailedException: Unexpected exception in 1: java.sql.SQLException: The statement has been cancelled or timed out.
> ERROR XCL52: The statement has been cancelled or timed out.
> java.sql.SQLException: Invalid transaction state.
> java.sql.SQLException: Invalid transaction state.
Test Failed.
*** End: SetQueryTimeoutTest jdk1.3.1 subset - 2.2 derbyall:jdbcapi 2006-09-10 11:07:26 ***

Comments

[A B]

Saw this on 10.3 trunk (svn 546339) on June 11th 2007, as well.

[Kathey Marsden]

Unchecking Regession checkbox as this is not a confirmed product regression

[A B]

For what it's worth, I saw this failure against 10.4 trunk (svn 579424) with weme6.1, as well. The test is now a JUnit test and the assertion failure is:

  Output at line 7 expected:<Statement 1 completed> but was:<Test SetQueryTimeoutTest FAILED>

That same diff also shows up in DERBY-2997.

[Kathey Marsden]

Saw this against weme6.1 on February 16, 2008 on trunk.

[Mike Matrigali]

Saw again on the trunk in the following results, most recently on 5/6/08
http://people.apache.org/~myrnavl/derby_test_results/main/windows/testlog/weme6.1/649735-suites.All_diff.txt
http://people.apache.org/~myrnavl/derby_test_results/main/windows/testlog/weme6.1/649735-suites.All_diff.txt
http://people.apache.org/~myrnavl/derby_test_results/main/windows/testlog/weme6.1/650349-suites.All_diff.txt
http://people.apache.org/~myrnavl/derby_test_results/main/windows/testlog/weme6.1/654381-suites.All_diff.txt

There was 1 failure:
1) SetQueryTimeoutTest(org.apache.derbyTesting.functionTests.tests.jdbcapi.JDBCHarnessJavaTest)junit.framework.ComparisonFailure: Output at line 7 expected:<Statement 1 completed> but was:<Test SetQueryTimeoutTest FAILED>
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:103)
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 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)
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)

[Mamta A. Satoor]

I have a scaled down reproducible version (it reproduces about once in 10runs of the program) of jdbcapi/SetQueryTimeoutTest.java. I have been running my test with weme 6.1 on the trunk. I will spend time on understanding the test better to see what sequence of sqls result into time out errors.

[Mamta A. Satoor]

Actually, it is not totally stand-alone test case. It is relying on a method declared inside SetQueryTimeoutTest.java for a user-defined function. So, in order to run the standalone JDBC program(DERBY_1848_Repro.java ), you need to have SetQueryTimeoutTest in your classpath. I will work on removing that dependency from the standalone java program.

[Mamta A. Satoor]

This updated reproducible program does not reference code inside SetQueryTimeoutTest.java

[Mamta A. Satoor]

After looking at the stand-alone test case more, what I have found is that it creates 100 Connection objects (2 would have been sufficient in the stand alone test case) and then sets TRANSACTION_READ_UNCOMMITTED on each of those Connection objects. Later, using the first Connection object, it creates 2 PreparedStatements, StatementA and StatementB. StatementA will later be set with a query timeoute of 1secs but StatementB has no timeout set on it. Next, using the second Connection object, the test program creates 2 PreparedStatements, StatementC and StatementD. Both these PreparedStatements do not have any timeout set on them. Then we start 4 separate threads using each of the PreparedStatement objects and fetch the data from them. (All the 4 PreparedStatements are made using the same SQL). The program expects only StatementA to timeout because it has non-zero query timeout set on it. It expects the other 3 PreparedStatements to finish with no timeouts. But for some reason, with weme6.1, the test times out every now and then for StatementB. I was wondering if this rings a bell to anyone. In the mean time, I am trying to debug this further.

[Mamta A. Satoor]

I just wanted to note the fact that this issue seems specific to J2ME implementation (I have only tested using IBM's J2ME implementation weme6.1). The same test program after repeated executions (I tried about 30 times) with IBM jdks 1.5 and 1.4 does not fail.

[Mamta A. Satoor]

Around each position moving request on a ResultSet object (next/previous/first/last etc), Derby pushes the StatementContext for that Statement (EmbedResultSet.movePosition). And once the ResultSet positioning is over, the StatementContext is popped back. This happens in EmbedResultSet.moveposition(int,int,String) method.

During the pushing of the StatementContext (in GenericLangaugeConnectionContext.pushStatementContext), we mark the StatementContext to
be in use by calling GenericStatementContext.setInUse. This setInUse method checks if query timeout is set on the Statement, and if yes, then it starts a Timer which uses CancelQueryTask to keep track of when the Statement execution should be marked timedout (The setting of the CancelQueryTask happens in GenericStatementContext.setInUse).

Once the requested positioning is done on the ResultSet object, Derby goes through the process of popping the StatementContext. This happens in GenericLangaugeConnectionContext.popStatementContext. Here, we mark the StatementContext as not in use since we are going to pop the StatementContext. This work gets done in GenericStatementContext.clearInUse. clearInUse checks if there is a timeout timer associated with the StatementContext (this association was done in pushStatementContext) and if yes, then it disassociates the timer and then marks the timer object as null. It also goes ahead and marks the cancel query flag to flase (cancellationFlag). The cancellationFlag tells whether the query associated with the StatementContext has exceeded the timeout limit. If user never set a query timeout on the Statement object, cancellationFlag will always be false. But if the user has set a query timeout, then this flag will be set to true by the CancelQueryTask when it finds that the Statement has run over it's limit of timeout amount. We do not throw an exception for query timeout as soon as the flag gets set to true. The cancellationFlag gets checked only when the user has requested a position movement on the ResultSet object.

So, one possible scenario can be that we push a StatementContext because user has requested say, ResultSet.next. During push, we set a query timeout timer because user has requested for timeout on the query. Then we go through the code for moving to next row in the ResultSet. The first thing we check there is if the query is marked cancelled (by checking cancellationFlag on StatementContext). If yes, then we throw an exception. But for this case, let's assume the query has not timeed out yet. Hence we go through the rest of the code for moving to next row. While we are doing
this(ie before we are finished with the code for moving to next row), say the timer times out and the timer goes and sets cancellationFlag to true (this happens in CancelQueryTask.run() which lives in the class GenericStatementContext). But this setting of flag is little too late for the current movement within the ResultSet object because we had just checked the flag earlier and it was set to false at that time. So, at this point, we just finish the ResultSet movement and then pop the StatementContext without throwning any exception. If the user has asked for another ResultSet movement after the current one, we will catch the query timeout, go through popping the current Statement Context and then throw an exception. The
popping of the StatementContext marks the StatementContext associated with the query timeout timer to false and then it nullifies the query timeout timer.

What seems to be happening in case of weme6.1 occassionally is that once the query timeout has been set and detected (which causes us to nullify the CancelQueryTask associated with the StatementContext being popped and throw exception), Derby somehow manages to set the query timeout to true again and we end up detecting it again and apparently we associate that timeout with a StatementContext that has not even requested a query timeout on it.


I wondered if someone familiar with this query timeout code can see what can cause us to set the timeout again when apparently we have nulled out the timer (in GenericLangaugeConnectionContext.popStatementContext).

[Mamta A. Satoor]

I think fixing DERBY-3338 will fix this jira entry as well. More info can be found in DERBY-3338.

[Mamta A. Satoor]

I am resolving this issue because I think fix for DERBY-3338 should fix this issue. If the problem reappears on the test machines, we can reopen this issue.

[Mamta A. Satoor]

Migrated the changes into 10.4 codeline(with revision 666871). Will work on migrating next to 10.3 codeline.

[Mamta A. Satoor]

Migrated the changes into 10.3.3.1 codeline also with revision 667136.