JDBC Instrumentation and ORA-01000: maximum open cursors exceeded

Question

I am trying to better instrument which web applications make use of Oracle (11g) connections in our Tomcat JDBC connection pool when a connection is created and closed; this way, we can see what applications are using connections by monitoring the V$SESSION table. This is working, but since adding this "instrumentation" I am seeing ORA-01000: maximum open cursors exceeded errors being logged and noticing some connections being dropped out of the pool during load testing (which is probably fine as I have testOnBorrow enabled, so I'm assuming the connection is being flagged as invalid and dropped from the pool).

I have spent the better part of the week scouring the internet for possible answers. Here is what I have tried (all result in the open cursors error after a period of time)...

The below methods are all called the same way...

On Create

1. We obtain a connection from the pool
2. We call a method that executes the below code, passing in the context name of the web application

On Close

1. We have the connection being closed (returned to the pool)
2. Before we issue close() on the connection, we call a method that executes the code below, passing in "Idle" as the name to store in V$SESSION

Method 1:

CallableStatement cs = connection.prepareCall("{call DBMS_APPLICATION_INFO.SET_MODULE(?,?)}");
try {
    cs.setString(1, appId);
    cs.setNull(2, Types.VARCHAR);
    cs.execute();
    log.trace(">>> Executed Oracle DBMS_APPLICATION_INFO.SET_MODULE with module_name of '" + appId + "'");
} catch (SQLException sqle) {
    log.error("Error trying to call DBMS_APPLICATION_INFO.SET_MODULE('" + appId + "')", sqle);
} finally {
    cs.close();
}

Method 2:

I upgraded to the 12c OJDBC driver (ojdbc7) and used the native setClientInfo method on the connection...

// requires ojdbc7.jar and oraclepki.jar to work (setEndToEndMetrics is deprecated in ojdbc7)
connection.setClientInfo("OCSID.CLIENTID", appId);

Method 3:

I'm currently using this method.

String[] app_instrumentation = new String[OracleConnection.END_TO_END_STATE_INDEX_MAX];
app_instrumentation[OracleConnection.END_TO_END_CLIENTID_INDEX] = appId;
connection.unwrap(OracleConnection.class).setEndToEndMetrics(app_instrumentation, (short)0);
// in order for this to be sent, a query needs to be sent to the database - this works fine when a 
// connection is created, but when it is closed, we need a little something to get the change into the db
// try using isValid()
connection.isValid(1);

Method 4:

String[] app_instrumentation = new String[OracleConnection.END_TO_END_STATE_INDEX_MAX];
app_instrumentation[OracleConnection.END_TO_END_CLIENTID_INDEX] = appId;
connection.unwrap(OracleConnection.class).setEndToEndMetrics(app_instrumentation, (short)0);
// in order for this to be sent, a query needs to be sent to the database - this works fine when a 
// connection is created, but when it is closed, we need a little something to get the change into the db
if ("Idle".equalsIgnoreCase(appId)) {
    Statement stmt = null;
    ResultSet rs = null;
    try {
        stmt = connection.createStatement();
        rs = stmt.executeQuery("select 1 from dual");
    } finally {
        if (rs != null) {
            rs.close();
        }
        if (stmt != null) {
            stmt.close();
        }
    }
}

When I query for open cursors, I notice the following SQL being returned on the account being used in the pool (for each connection in the pool)...

select NULL NAME, -1 MAX_LEN, NULL DEFAULT_VALUE, NULL DESCR

This does not explicitly exist anywhere in our code, so I can only assume it is coming from the pool when running the validation query (select 1 from dual) or from the setEndToEndMetrics method (or from the DBMS_APPLICATION_INFO.SET_MODULE proc, or from the isValid() call). I tried to be explicit in creating and closing Statement (CallableStatement) and ResultSet objects in methods 1 and 4, but they made no difference.

I don't want to increase the number of allowed cursors, as this will only delay the inevitable (and we have never had this issue until I added in the "instrumentation").

I've read through the excellent post here (java.sql.SQLException: - ORA-01000: maximum open cursors exceeded), but I must still be missing something. Any help would be greatly appreciated.

Answer 1

So Mr. Poole's statement: "that query looks like it's getting fake metadata" set off a bell in my head.

I started to wonder if it was some unknown remnant of the validation query being run on the testOnBorrow attribute of the pool's datasource (even though the validation query is defined as select 1 from dual). I removed this from the configuration, but it had no effect.

I then tried removing the code that sets the client info in V$SESSION (Method 3 above); Oracle continued to show that unusual query and after only a few minutes, the session would hit the maximum open cursors limit.

I then found that there was a "logging" method in our DAO class that logged some metadata from the connection object (values for settings like current auto commit, current transaction isolation level, JDBC driver version, etc.). Within this logging was the use of the getClientInfoProperties() method on the DatabaseMetaData object. When I looked at the JavaDocs for this method, it became crystal clear where that unusual query was coming from; check it out...

ResultSet java.sql.DatabaseMetaData.getClientInfoProperties() throws SQLException

Retrieves a list of the client info properties that the driver supports. The result set contains the following columns 

1. NAME String=> The name of the client info property
2. MAX_LEN int=> The maximum length of the value for the property
3. DEFAULT_VALUE String=> The default value of the property
4. DESCRIPTION String=> A description of the property. This will typically contain information as to where this property is stored in the database. 

The ResultSet is sorted by the NAME column 

Returns:

A ResultSet object; each row is a supported client info property

You can clearly see that unusual query (select NULL NAME, -1 MAX_LEN, NULL DEFAULT_VALUE, NULL DESCR) matches what the JavaDocs say about the DatabaseMetaData.getClientInfoProperties() method. Wow, right!?

This is the code that was performing the function. As best as I can tell, it looks correct from a "closing of the ResultSet" standpoint - not sure what was happening that would keep the ResultSet open - it clearly being closed in the finally block.

log.debug(">>>>>> DatabaseMetaData Client Info Properties (jdbc driver)...");
ResultSet rsDmd = null;
try {
    boolean hasResults = false;
    rsDmd = dmd.getClientInfoProperties();
    while (rsDmd.next()) {
        hasResults = true;
        log.debug(">>>>>>>>> NAME = '" + rsDmd.getString("NAME") + "'; DEFAULT_VALUE = '" + rsDmd.getString("DEFAULT_VALUE") + "'; DESCRIPTION = '" + rsDmd.getString("DESCRIPTION") + "'");
    }
    if (!hasResults) {
        log.debug(">>>>>>>>> DatabaseMetaData Client Info Properties was empty (nothing returned by jdbc driver)");
    }
} catch (SQLException sqleDmd) {
    log.warn("DatabaseMetaData Client Info Properties (jdbc driver) not supported or no access to system tables under current id");
} finally {
    if (rsDmd != null) {
        rsDmd.close();
    }
}

Looking at the logs, when an Oracle connection was used, the >>>>>>>>> DatabaseMetaData Client Info Properties was empty (nothing returned by jdbc driver) line was logged, so an exception wasn't being thrown, but no record was being returned either. I can only assume that the ojdbc6 (11.2.0.x.x) driver doesn't properly support the getClientInfoProperties() method - it is weird (I think) that an exception wasn't being thrown, as the query itself is missing the FROM keyword (it won't run when executed in TOAD for example). And no matter what, the ResultSet should have at least been getting closed (the connection itself would still be in use though - maybe this causes Oracle to not release the cursors even though the ResultSet was closed).

So all of the work I was doing was in a branch (I mentioned in a comment to my original question that I was working in trunk - my mistake - I was in a branch that was already created thinking it was based on trunk code and not modified - I failed to do my due diligence here), so I checked the SVN commit history and found that this additional logging functionality was added by a fellow teammate a couple of weeks ago (fortunately it hasn't been promoted to trunk or to higher environments - note this code works fine against our Sybase database). My update from the SVN branch brought in his code, but I never really paid attention to what got updated (my bad). I spoke with him about what this code was doing against Oracle, and we agreed to remove the code from the logging method. We also put in place a check to only log the connection metadata when in our development environment (he said he added this code to help troubleshoot some driver version and auto commit questions he had). Once this was done, I was able to run my load tests without any open cursor issues (success!!!).

Anyway, I wanted to answer this question because when I searched for select NULL NAME, -1 MAX_LEN, NULL DEFAULT_VALUE, NULL DESCR and ORA-01000 open cursors no credible hits were returned (the majority of the hits returned were to make sure you are closing your connection resources, i.e., ResultSets, Statements, etc.). I think this shows it was the database metadata query through JDBC against Oracle was the culprit of the ORA-01000 error. I hope this is useful to others. Thanks.