Thursday, May 21, 2020

DBCA Reports ORA-46385 When Oracle Home Has Unified Auditing Enabled

Running dbca in silent mode reports ORA-46385 if the Oracle home has unified auditing is enabled. Below is the output on the shell prompt (only relevant section of the output is shown). This was on 19c.
Creating data dictionary views
33% complete
38% complete
39% complete
40% complete
[WARNING] ORA-46385: DML and DDL operations are not allowed on table

41% complete
46% complete
49% complete
52% complete
57% complete
Oracle Text
Trace files shows the same.
[Thread-242] [ 2020-02-06 12:23:53.087 UTC ] [BasicStep.handleNonIgnorableError:541]  oracle.sysman.assistants.util.SilentMessageHandler@3a6532cd:messageHandler
[Thread-242] [ 2020-02-06 12:23:53.087 UTC ] [BasicStep.handleNonIgnorableError:542]  ORA-46385: DML and DDL operations are not allowed on table
:msg
WARNING: Feb 06, 2020 12:23:53 PM oracle.assistants.common.base.util.AssistantAdvisor logMessage
WARNING: [ 2020-02-06 12:23:53.088 UTC ] [WARNING] ORA-46385: DML and DDL operations are not allowed on table


The dbca can run till the end despite the error. However, if a clean error free installation is preferred then turn off the unified auditing on the Oracle home before running dbca. There's no error in this case (output shown around same % mark where error happened before). Enable unified auditing once database is created.
Creating data dictionary views
33% complete
38% complete
39% complete
40% complete
41% complete
46% complete
49% complete
52% complete
57% complete
Oracle Text

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();
    }

}

Wednesday, April 15, 2020

Auto Commit State Persists After Connection Close on UCP

By default connections checked out of universal connection pool (UCP) will have a auto commit state of true. This could be changed by setting the auto commit state on the connection. Another way to change is to change the connection pool's default setting for auto commit.
Comparing implicit connection cache (ICC) pools and UCP it appears that in UCP the auto commit state persist even after connection is closed. This means if a connection changes the auto commit state and return it to the pool and same connection is checked out later, it will have the changed auto commit state and not the default value.
This behaviour was not seen on ICC pools (ICC is considered deprecated). Once the connection is returned to the pool and checked out again, it will have the default behaviour.
The test cases is given at the end of the post. Comment/uncomment either getUCPDS or getICCDS methods to run the desired test case. The pool size is set to 1 to keep things simple. But even if it's increased the test case would work. Below is an explanation of the output seen.

UCP test case output
First up is checking the default state of auto commit
Auto commit status after checking out of the pool 

0 true
Next up the auto commit state is changed to opposite of the default. If default is true, then set to false and vice versa. Afterwards verify if the changed state is reflected on the connection. Since default auto commit state was true the opposite was false. As such now the auto commit state is reflected as false.
Setting auto commit to opposite

0 false
Following the auto commit state change the connection is closed and returned to the pool.
Connections closed and returned to the pool
Finally the connection is checked out of the pool again and auto commit state is verified. In UCP the connection will have changed state of auto commit rather than the default value, even though this is a "new" connection checked out of the pool (pools never close the underlying physical connection. So new is a logical new rather than an actual new physical connection).
Auto commit status after checking out of the pool 

0 : false

ICC test case output
The ICC test case output is same except for last step. It will also have a true state for default auto commit setting. The default state is changed to false and connection is returned to the pool.
Auto commit status after checking out of the pool 

0 true

 Setting auto commit to opposite 

0 false

Connections closed and returned to the pool 
When the connection is checked out next time from the pool it will have the default state instead of the previously changed state (unlike UCP).
Auto commit status after checking out of the pool 

0 : true
These test were carried out using ojdbc10.jar and ucp.jar versions 19.6.



The behaviour seen on UCP is same even if the default auto commit state is changed on the pool level by setting the OracleConnection.CONNECTION_PROPERTY_AUTOCOMMIT to false. In such a case the connection checked out of the pool will have auto commit set to false. But any change to this will persist same as shown above.
Auto commit status after checking out of the pool 

0 false

 Setting auto commit to opposite 

0 true

Connections closed and returned to the pool 

Auto commit status after checking out of the pool 

0 : true
When a SR was raised with regard to the difference in behaviour, Oracle support stated "When connections are created and placed in the UCP pool the connection properties that are associated with each connection remain for the duration of the connection". However, this fact is not reflected on the UCP documentation but Oracle support insisted this has always been the case. Following that the same test case was tested against ojdbc6.jar and ucp.jar of 11.2.0.1 and showed the same test output. It seems rightly or wrongly the UCP had the same behaviour throughout.
However, this difference between ICC and UCP is not listed anywhere on the documentation. Any migration from ICC to UCP should watch out for this change in behaviour.

Related Posts
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

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

/**
 *
 * @author Asanga
 */
public class TestUCPAutoCommit {

    static String URL = "jdbc:oracle:thin:@192.168.1.100:1521:enlt1";
    static String username = "asanga";
    static String password = "asanga";
    static int POOL_SIZE = 1;

    static DataSource ds;

    public static void main(String[] args) throws SQLException, UniversalConnectionPoolException, InterruptedException {

        ds = getUCPDS(); // UCP test case

//        ds = getICCDS(); // ICC test case
        
        Connection[] cons = new Connection[POOL_SIZE];

        System.out.println("Auto commit status after checking out of the pool \n");
        for (int i = 0; i < cons.length; i++) {

            cons[i] = ds.getConnection();
            System.out.println(i + " " + cons[i].getAutoCommit());

        }

        System.out.println("\n Setting auto commit to opposite \n");
        for (int i = 0; i < cons.length; i++) {

            cons[i].setAutoCommit(!cons[i].getAutoCommit());
            System.out.println(i + " " + cons[i].getAutoCommit());

        }
        System.out.println("\nConnections closed and returned to the pool \n");
        for (Connection conn : cons) {
            conn.close();
        }

        System.out.println("Auto commit status after checking out of the pool \n");
        for (int i = 0; i < cons.length; i++) {

            cons[i] = ds.getConnection();
            System.out.println(i + " : " + cons[i].getAutoCommit());

        }

    }

    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(POOL_SIZE);
        ds.setMinPoolSize(POOL_SIZE);
        ds.setMaxPoolSize(POOL_SIZE);

        /* uncomment below to set default state of auto commit to false */ 
        
//        Properties connProps = new Properties();
//        connProps.put(OracleConnection.CONNECTION_PROPERTY_AUTOCOMMIT, "false");
//        ds.setConnectionProperties(connProps);


        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", POOL_SIZE + "");
        properties.setProperty("MaxLimit", POOL_SIZE + "");
        properties.setProperty("InitialLimit", POOL_SIZE + "");

        ds.setConnectionCachingEnabled(true);

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

        return ds;
    }

}