Issue Details (XML | Word | Printable)

Key: NUCRDBMS-662
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Major Major
Assignee: Unassigned
Reporter: Gerrit Volkenborn
Votes: 1
Watchers: 1
Operations

If you were logged in you would be able to see more operations.
DataNucleus Store RDBMS

ORA-01000: Maximum open cursors exceeded

Created: 22/Mar/13 10:13 AM   Updated: 06/Apr/13 10:00 AM   Resolved: 04/Apr/13 09:21 AM
Component/s: Queries
Affects Version/s: 3.2.0.m4, 3.2.0.release
Fix Version/s: 3.2.1

File Attachments: 1. Zip Archive test_failing.zip (4 kB)


Forum Thread URL: http://www.datanucleus.org/servlet/forum/viewthread_thread,7469
Datastore: Oracle


 Description  « Hide
query.closeAll() and query.close(result) will not close the cursor anymore; it remains open as long as the database session exists.

The issue does not occur in 3.0.11 but can be reproduced reliably in 3.2.0-release.

Testcase attached.

Sort Order: Ascending order - Click to sort in descending order
Gerrit Volkenborn added a comment - 22/Mar/13 10:14 AM - edited
Tested on m-versions: 3.2.0-m3 works, 3.2.0-m4 first has the bug.

Gerrit Volkenborn added a comment - 22/Mar/13 02:21 PM
Comparison between m-3 and m-4 logs:

m3:

593 [main] DEBUG DataNucleus.Query - SQL Query : "select a.value, s.sid from v$sesstat a, v$statname b, v$session s where a.statistic# = b.statistic# and s.sid = a.sid and b.name = 'opened cursors current' and s.username = 'TEST' and 0=0"
610 [main] DEBUG DataNucleus.Connection - Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@50e1cd" opened with isolation level "read-committed" and auto-commit=false
611 [main] DEBUG DataNucleus.Transaction - Running enlist operation on resource: org.datanucleus.store.rdbms.ConnectionFactoryImpl$EmulatedXAResource@523e0f04, error code TMNOFLAGS and transaction: [DataNucleus Transaction, ID=Xid=
611 [main] DEBUG DataNucleus.Connection - Managed connection org.datanucleus.store.rdbms.ConnectionFactoryImpl$EmulatedXAResource@523e0f04 is starting for transaction Xid=
611 [main] DEBUG DataNucleus.Connection - Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@4682e581 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@50e1cd, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextThreadedImpl@4f1e7098 in factory=ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@3ba99c51]
649 [main] DEBUG DataNucleus.Datastore - Closing PreparedStatement "oracle.jdbc.driver.OraclePreparedStatementWrapper@2ffc572f"
650 [main] DEBUG DataNucleus.Datastore.Native - select a.value, s.sid from v$sesstat a, v$statname b, v$session s where a.statistic# = b.statistic# and s.sid = a.sid and b.name = 'opened cursors current' and s.username = 'TEST' and 0=0
652 [main] DEBUG DataNucleus.Datastore.Retrieve - Execution Time = 2 ms
659 [main] INFO DataNucleus.Query - Reading in results for query "org.datanucleus.store.rdbms.query.SQLQuery@0" since the connection used is closing
run #0: 1 open cursors on SID 1103
run #0: 0 open cursors on SID 1117
661 [main] DEBUG DataNucleus.Query - SQL Query : "select a.value, s.sid from v$sesstat a, v$statname b, v$session s where a.statistic# = b.statistic# and s.sid = a.sid and b.name = 'opened cursors current' and s.username = 'TEST' and 1=1"
661 [main] DEBUG DataNucleus.Connection - Connection found in the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@4682e581 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@50e1cd, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextThreadedImpl@4f1e7098 in factory=ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@3ba99c51]
661 [main] DEBUG DataNucleus.Datastore - Closing PreparedStatement "oracle.jdbc.driver.OraclePreparedStatementWrapper@1f317315"
661 [main] DEBUG DataNucleus.Datastore.Native - select a.value, s.sid from v$sesstat a, v$statname b, v$session s where a.statistic# = b.statistic# and s.sid = a.sid and b.name = 'opened cursors current' and s.username = 'TEST' and 1=1
662 [main] DEBUG DataNucleus.Datastore.Retrieve - Execution Time = 1 ms
662 [main] INFO DataNucleus.Query - Reading in results for query "org.datanucleus.store.rdbms.query.SQLQuery@0" since the connection used is closing
run #1: 1 open cursors on SID 1103
run #1: 0 open cursors on SID 1117

m-4:

588 [main] DEBUG DataNucleus.Query - SQL Query : "select a.value, s.sid from v$sesstat a, v$statname b, v$session s where a.statistic# = b.statistic# and s.sid = a.sid and b.name = 'opened cursors current' and s.username = 'TEST' and 0=0"
605 [main] DEBUG DataNucleus.Connection - Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@65ca88c8" opened with isolation level "read-committed" and auto-commit=false
606 [main] DEBUG DataNucleus.Transaction - Running enlist operation on resource: org.datanucleus.store.rdbms.ConnectionFactoryImpl$EmulatedXAResource@7ec21f4c, error code TMNOFLAGS and transaction: [DataNucleus Transaction, ID=Xid=
606 [main] DEBUG DataNucleus.Connection - Managed connection org.datanucleus.store.rdbms.ConnectionFactoryImpl$EmulatedXAResource@7ec21f4c is starting for transaction Xid=
606 [main] DEBUG DataNucleus.Connection - Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@74bdf7a0 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@65ca88c8, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextThreadedImpl@4e97264f in factory=ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@63cc6540]
645 [main] DEBUG DataNucleus.Datastore - Closing PreparedStatement "org.datanucleus.store.rdbms.datasource.dbcp.DelegatingPreparedStatement@15fec1d"
647 [main] DEBUG DataNucleus.Datastore.Native - select a.value, s.sid from v$sesstat a, v$statname b, v$session s where a.statistic# = b.statistic# and s.sid = a.sid and b.name = 'opened cursors current' and s.username = 'TEST' and 0=0
648 [main] DEBUG DataNucleus.Datastore.Retrieve - Execution Time = 1 ms
656 [main] INFO DataNucleus.Query - Reading in results for query "org.datanucleus.store.rdbms.query.SQLQuery@0" since the connection used is closing
run #0: 0 open cursors on SID 1109
run #0: 1 open cursors on SID 1117
657 [main] DEBUG DataNucleus.Query - SQL Query : "select a.value, s.sid from v$sesstat a, v$statname b, v$session s where a.statistic# = b.statistic# and s.sid = a.sid and b.name = 'opened cursors current' and s.username = 'TEST' and 1=1"
657 [main] DEBUG DataNucleus.Connection - Connection found in the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@74bdf7a0 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@65ca88c8, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextThreadedImpl@4e97264f in factory=ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@63cc6540]
658 [main] DEBUG DataNucleus.Datastore - Closing PreparedStatement "org.datanucleus.store.rdbms.datasource.dbcp.DelegatingPreparedStatement@7df766ae"
658 [main] DEBUG DataNucleus.Datastore.Native - select a.value, s.sid from v$sesstat a, v$statname b, v$session s where a.statistic# = b.statistic# and s.sid = a.sid and b.name = 'opened cursors current' and s.username = 'TEST' and 1=1
659 [main] DEBUG DataNucleus.Datastore.Retrieve - Execution Time = 1 ms
659 [main] INFO DataNucleus.Query - Reading in results for query "org.datanucleus.store.rdbms.query.SQLQuery@0" since the connection used is closing
run #1: 0 open cursors on SID 1109
run #1: 2 open cursors on SID 1117

So, m-3 shows
Closing PreparedStatement "oracle.jdbc.driver.OraclePreparedStatementWrapper@2ffc572f"

and m-4 shows
Closing PreparedStatement "org.datanucleus.store.rdbms.datasource.dbcp.DelegatingPreparedStatement@15fec1d"

That's the only difference I could spot.

Gerrit Volkenborn added a comment - 22/Mar/13 04:58 PM - edited
Another interesting fact: when using the Merlia driver (com.inet.ora.OraDriver), earlier versions will fail as well (like m-2).
When using the orginal (oracle.jdbc.OracleDriver), everything up to m-3 is fine!

Note: with the Merlia driver, the amount of open cursors will rise until it hits 500 and then remain constant.

Rebecca Martinez added a comment - 22/Mar/13 07:26 PM
Elaborating on the comment, found in the DatanucleusCursorsTest.java, "The query needs to use a different syntax each time"....

We noticed that the amount of cursors opened for a repeated query depended on how the query was structured. The following illustrates three different approaches for getting a job. Test 1 and 2 will not open a cursor for each job id. Test 3 will open a cursor for each query if the id is different. In all three tests the cursors are left open. However, the maximum open cursors exceeded exception only occurs when using Test 3 in a repeated loop because a cursor is left open for each query.

The test was shown using oracle6.jar (oracle.jdbc.OracleDriver) and DataNucleus release 3.2.0.
 
public JobFlowSubject getJobTest1(long id)
{
Query query = PM.newNamedQuery(JobFlowSubject.class, "JobFlowSubject.findByJobId");
query.setUnique(true);

JobFlowSubject job = (JobFlowSubject) query.execute(id);

query.closeAll();

return job;
}

public JobFlowSubject getJobTest2(long id)
{
Query query = PM.newQuery(JobFlowSubject.class);
query.setFilter("JobId == id");
query.declareParameters("long id");
query.setUnique(true);

JobFlowSubject job = (JobFlowSubject) query.execute(id);

query.closeAll();

return job;
}

public JobFlowSubject getJobTest3(long id) throws Exception
{
Query query = PM.newQuery(JobFlowSubject.class);
query.setFilter(String.format("JobId == %d", id));
query.setUnique(true);

JobFlowSubject job = (JobFlowSubject) query.execute();

query.closeAll();

return job;
}

Chris Colman added a comment - 22/Mar/13 07:57 PM - edited
Rebecca it sounds like your hunch makes sense: It might be that the cursor isn't being freed in all cases but because Test 2 has an identical filter containing a parameter name in each call only one cursor is ever used but Test 3, having a different filter each call, uses a new filter with each call - causing eventual depletion.

Andy Jefferson added a comment - 24/Mar/13 06:52 PM - edited
Evidently putting a link to the test case format on the front page of JIRA, referencing it in "datanucleus.org" website, and putting it on the forum is not enough (for some). A testcase is defined at http://www.datanucleus.org/project/problem_jdo_testcase.html
What is attached here wouldn't run on my Oracle 11 XE instance on Linux ("table or view doesn't exist"), and doesn't fit that standard anyway, and I've got very little spare time for such things (and that spare time for this week has just been wasted). Consequently I'll hand it back to the people who have the problem for them to develop a fix. Attach your patch to plugin "store.rdbms" SVN trunk to this issue when you've finished it.

Since you've gone to the effort of working out that your problem is not present in 3.2.0.M3 of store.rdbms, yet is in 3.2.0.M4 then you could easily enough just look at JIRA for that release for what was changed, namely http://www.datanucleus.org/servlet/jira/secure/IssueNavigator.jspa?reset=true&mode=hide&pid=10144&fixfor=11883
Perhaps something in DBCP caching of PreparedStatements is buggy ? (since that is enabled in 3.2.0.M4, but wasn't before). But then there are many other connection pools supported and trivial to use any other one. Or maybe its something else. Anyway, that's only discovered by investigating it. Thanks.

Andy Jefferson added a comment - 25/Mar/13 10:34 AM
Example of a test, using Oracle and multiple queries, with query.closeAll, which works (Linux, Oracle XE 11g, 11.2.0.3 JDBC driver).

Gerrit Volkenborn added a comment - 25/Mar/13 02:12 PM
In case you want to review this issue once more, I adapted your test case so it fails now, and also added both query types (JDO and SQL).

There are two preconditions to the failure:

one, the query needs to be different every time (JDOQuery obviously needs to access a member of the queried class on top of that)
two, the result set may not be fully iterated because the cursor is removed then, so you may not use a for construct, or you need to break out of it.

Andy Jefferson added a comment - 04/Apr/13 09:21 AM
As per my suggestion on this issue, disabling "preparedStatement pooling" when using DBCP makes that test pass. Use of C3P0 or BoneCP with preparedStatement pooling unchanged makes that test pass.

Conclusion : DBCP PreparedStatement pooling is buggy, and SVN trunk now sets datanucleus.connectionPool.maxStatements to 0 as the default. The provided test passes. If some other situation have this "problem" after setting this property or using SVN trunk then raise an issue with a valid testcase