Thursday, May 14, 2020

UCP Connection Not Releasing Resources Immediately When Closed

JDBC connection created from a UCP pool does not release database resources immediately when close method is called. Java spec states calling close method "releases this Connection object's database and JDBC resources immediately instead of waiting for them to be automatically released. Calling the method close on a Connection object that is already closed is a no-op. It is strongly recommended that an application explicitly commits or rolls back an active transaction prior to calling the close method. If the close method is called and there is an active transaction, the results are implementation-defined."
It seems the implementation differ between implicit connection caching (ICC) pools and and UCP.
In particular UCP connections holds on to DML related locks of uncommitted transactions. Not releasing of DML related locks when close is called leads to locking and misleading error reporting such as number of rows inserted/updated. DML related locks get released only during a rollback or a commit. Connections out of an implicit connection caching (ICC) pools release the DML locks after call to close method. Issue was recreated using ojdbc10.jar (version 19.7).
The test case (code given at the end of the post) insert a single row to a table with a primary key and close the connection (without commit or rollback as those releases the locks). Then connection is checked out of the pool and it will report unique key violation even though no rows were inserted during the previous step. Querying v$lock shows table (TM) and row locks (TX) still being held by the session.
If a commit is called on connection checked out second time from the pool the previous transaction commits. It seems the transaction span connection close.
Connection out of a ICC pool doesn't exhibit this behaviour. These connections only old the TM and TX locks until connections is closed (if commit or rollback is not called before that). Once close method is called all table and row level locks are released.
Below is the output explanation of the test code given for UCP test case.
The connection pool is created with a single connection. There's no difference if more connections are the pool behaviour is the same. Only difference would be instead of unique constraint violation the second session would hang until first one is commit or rollback. First up the session id and serial# is printed. This is in case want to query the DB to verify the session locks held by the particular session..
Getting Session ID
SID 592 Serial# 54115
Test code runs to insert a single row to an empty table (table DML is given in the java code). The connection close without commit or rollback.
Insert a row and close connection without commit
Verify connection is closed. This stage the connection is returned to the pool.
Is Closed? true
Check out the connection from the pool and check the resources held by the connection. Since pool only has 1 connection it would be the same physical connection checked out previously. As seen from the output it is still holding on the table (TM) and row level (TX) locks.
Getting the connection from the pool

Resource Locks held by the previously closed session

SID TYPE ID1 ID2 LMODE Request CTime BLOCK
592 AE 100 0 4 0 1 2
592 TM 1838626 0 3 0 0 2
592 TX 29229081 62458 6 0 0 2
Moreover the connection states it had inserted one row even though it was closed and checked out again

Number of rows inserted

Rows inserted : 1
Running the same insert again results in unique key violation. Even though no rows were committed to the database. Querying the table will show 0 rows.
 Running insert again will error due to locks held by previously closed session

Getting Session ID
SID 592 Serial# 54115
Exception in thread "main" java.sql.SQLIntegrityConstraintViolationException: ORA-00001: unique constraint (ASANGA.SYS_C003916184) violated


Running the ICC pool test case doesn't result in any errors and shows 0 rows inserted for connection when checked out second time from the pool. No table and row level locks are held after connection close. Output for ICC pool test case is shown below.
Getting Session ID
SID 400 Serial# 18301

Insert a row and close connection without commit

Is Closed? true

Getting the connection from the pool


Resource Locks held by the previously closed session

SID TYPE ID1 ID2 LMODE Request CTime BLOCK
400 AE 100 0 4 0 2 2

Number of rows inserted

Rows inserted : 0

 Running insert again will error due to locks held by previously closed session

Getting Session ID
SID 400 Serial# 18301
When a SR was raised Oracle responded that this is tracked under unpublished bug 28281115. There seem to be patch available but need to be ported to 19c version. Post will be updated once the solution is provided. In mean time make note of this behaviour change when moving from ICC to UCP.

Related Posts
Auto Commit State Persists After Connection Close on UCP
java.sql.SQLException: Could not commit with auto-commit set on When Using 12c JDBC Driver
Change in 12c JDBC Behavior - setDate & getDate Does Not Truncate Timestamp
JDBC Auto Commit and Log File Sync
UCP Connections Fail to Connect to DB in Mount Mode With ORA-12504 TNS:listener was not given the SID in CONNECT_DATA
TimesTen JDBC Connection Pool Using UCP (Universal Connection Pool)
Using Oracle Connection Pools with ActiveMQ
JDBC Client Failover in Data Guard Configuration with PDBs

Update on 2020-06-01

Patch for bug 28281115 (pending transaction is not committed implicitly on conn return) is now available for 18.3 and 19.3 - 19.6 (19.7 has been requested). This fixed the issue of not releasing table locks. However, still there's a difference in behaviour between ICC and UCP. The UCP does an implicit commit when closing the connection while ICC does an implicit rollback. Make note of these differences when migrating from ICC to UCP.

Java Test Case
import java.sql.*;
import java.util.Properties;
import oracle.ucp.jdbc.PoolDataSource;
import oracle.ucp.jdbc.PoolDataSourceFactory;
import javax.sql.DataSource;
import oracle.jdbc.pool.OracleConnectionCacheManager;
import oracle.jdbc.pool.OracleDataSource;

/**
 *
 * @author Asanga
 */
// table used for test case
//create table ucptest (a number, b varchar2(100), primary key (a));
public class UCPLockTest {

    static int MINVALUE = 1;
    static int MAXVALUE = 1;
    static int INITIALVALUE = 1;
    static String URL = "jdbc:oracle:thin:@192.168.1.100:1521:cgenlt1";
    static String username = "asanga";
    static String password = "asanga321";

    static int INACTIVE_TIMEOUT = 60;
    static int ABANDON_TIMEOUT = 60;
    static int PROPCHECK=45;

    static int SID;

    static DataSource ds;
    
    public static void main(String[] args) throws SQLException {

        ds = getUCPDS(); // UCP test case
//        ds = getICCDS(); //ICC test case
      

        Connection con = ds.getConnection();
        con.setAutoCommit(false);

        System.out.println("Getting Session ID");
        getSessionID(con);

        System.out.println("\nInsert a row and close connection without commit\n");
        runInsertWithoutCommit(con);
        System.out.println("Is Closed? "+con.isClosed());

        System.out.println("\nGetting the connection from the pool\n");
        con = ds.getConnection();
        con.setAutoCommit(false);
        

        System.out.println("\nResource Locks held by the previously closed session\n");
        listLocksHeldBySession(con);

        System.out.println("\nNumber of rows inserted\n");
        getRowCount(con);

        System.out.println("\n Running insert again will error due to locks held by previously closed session\n");

        System.out.println("Getting Session ID");
        getSessionID(con);

        runInsertWithoutCommit(con);

    }

    static DataSource getUCPDS() throws SQLException {

        PoolDataSource ds = PoolDataSourceFactory.getPoolDataSource();
        ds.setConnectionFactoryClassName("oracle.jdbc.pool.OracleDataSource");
        ds.setURL(URL);
        ds.setUser(username);
        ds.setPassword(password);
        ds.setInitialPoolSize(INITIALVALUE);
        ds.setMinPoolSize(MINVALUE);
        ds.setMaxPoolSize(MAXVALUE);

        ds.setInactiveConnectionTimeout(INACTIVE_TIMEOUT);
        ds.setAbandonedConnectionTimeout(ABANDON_TIMEOUT);
        ds.setPropertyCycle(PROPCHECK);

        return ds;

    }

    static DataSource getICCDS() throws SQLException {

        OracleDataSource ds = new OracleDataSource();
        ds.setURL(URL);
        ds.setUser(username);
        ds.setPassword(password);

        Properties properties = new Properties();
        properties.setProperty("MinLimit", MINVALUE+"");
        properties.setProperty("MaxLimit", MAXVALUE+"");
        properties.setProperty("InitialLimit", INITIALVALUE+"");
        properties.setProperty("InactivityTimeout", INACTIVE_TIMEOUT+"");
        properties.setProperty("AbandonedConnectionTimeout", ABANDON_TIMEOUT+"");
        properties.setProperty("PropertyCheckInterval", PROPCHECK+"");

        ds.setConnectionCachingEnabled(true);

        OracleConnectionCacheManager cache = OracleConnectionCacheManager.getConnectionCacheManagerInstance();
        cache.createCache("asa", ds, properties);
        
        return ds;
    }

    static void getSessionID(Connection con) throws SQLException {

        PreparedStatement pr = con.prepareStatement("select sid,serial# from v$session where sid=sys_context('USERENV','SID')");
        ResultSet rs = pr.executeQuery();
        while (rs.next()) {
            System.out.println("SID " + rs.getInt(1) + " Serial# " + rs.getInt(2));
            SID = rs.getInt(1);
        }
        rs.close();
        pr.close();

    }

    static void runInsertWithoutCommit(Connection con) throws SQLException {

        PreparedStatement pr = con.prepareStatement("insert into ucptest values (?,?)");
        pr.setInt(1, 1);
        pr.setString(2, "test " + new Date(System.currentTimeMillis()).toString());
        pr.execute();

        con.close();

    }

    static void listLocksHeldBySession(Connection con) throws SQLException {

        PreparedStatement pr = con.prepareStatement("select sid,type,id1,id2,lmode,request,ctime,block from v$lock where sid=?");
        pr.setInt(1, SID);
        ResultSet rs = pr.executeQuery();
        System.out.println("SID\tTYPE\tID1\tID2\tLMODE\tRequest\tCTime\tBLOCK");

        while (rs.next()) {
            int i = 0;
            System.out.print(rs.getInt(++i) + "\t");
            System.out.print(rs.getString(++i) + "\t");
            System.out.print(rs.getInt(++i) + "\t");
            System.out.print(rs.getInt(++i) + "\t");
            System.out.print(rs.getInt(++i) + "\t");
            System.out.print(rs.getInt(++i) + "\t");
            System.out.print(rs.getInt(++i) + "\t");
            System.out.println(rs.getInt(++i));
        }
        rs.close();
        pr.close();

    }

    static void getRowCount(Connection con) throws SQLException {

        PreparedStatement pr = con.prepareStatement("select count(*) from ucptest");
        ResultSet rs = pr.executeQuery();

        while (rs.next()) {

            System.out.println("Rows inserted : " + rs.getInt(1));
        }

        rs.close();
        pr.close();
    }

}