Tuesday, May 26, 2020

Reread resulted in same corrupt block on file 'spfil.ora' blockno=1

Active database duplication for standby fails with an error specific to 4k sector size. The primary database is Oracle restart with ASM where disks are on 4k emulation mode (512 logical sector and 4k physical sector). The spfile of the primary reside in the ASM disk (19c DB). During the active database duplicate command the primary would copy the spfile (with relavent changes specified by the duplication command) to the standby instance. But this location is not the ASM but $ORACLE_HOME/dbs. However, when the 4k emulation mode is involved this copying spfile from ASM to file system location results in following error on the primary DB rman session.
RMAN> duplicate target database for standby from active database
2> spfile
3> parameter_value_convert 'masterdb','masterdr','MASTERDB','MASTERDR'
set db_name='masterdb'
4> 5> set db_unique_name='masterdr'
6> set fal_server='masterdbtns'
7> set log_archive_dest_1='location=use_db_recovery_file_dest valid_for=(all_logfiles,all_roles) db_unique_name=masterdr NOREOPEN ALTERNATE=log_archive_dest_2'
8> set log_archive_dest_3='service=masterdbtns LGWR ASYNC NOAFFIRM max_failure=10 reopen=60 valid_for=(online_logfiles,primary_role) db_unique_name=masterdb'
9> set local_listener='LISTENER_MASTERDR';

Starting Duplicate Db at 28-JUN-19
using target database control file instead of recovery catalog
allocated channel: ORA_AUX_DISK_1
channel ORA_AUX_DISK_1: SID=268 device type=DISK

contents of Memory Script:
{
   backup as copy reuse
   passwordfile auxiliary format  '/opt/app/oracle/product/19.x.0/dbhome_1/dbs/orapwmasterdr'   targetfile
 '+DATA/masterdb/parameterfile/spfile.293.1012128045' auxiliary format
 '/opt/app/oracle/product/19.x.0/dbhome_1/dbs/spfilemasterdr.ora'   ;
   sql clone "alter system set spfile= ''/opt/app/oracle/product/19.x.0/dbhome_1/dbs/spfilemasterdr.ora''";
}
executing Memory Script

Starting backup at 28-JUN-19
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=575 device type=DISK
Finished backup at 28-JUN-19

sql statement: alter system set spfile= ''/opt/app/oracle/product/19.x.0/dbhome_1/dbs/spfilemasterdr.ora''


Reread resulted in same corrupt block on file '/opt/app/oracle/product/19.x.0/dbhome_1/dbs/spfilemasterdr.ora' blockno=1
Reread resulted in same corrupt block on file '/opt/app/oracle/product/19.x.0/dbhome_1/dbs/spfilemasterdr.ora' blockno=1
Reread resulted in same corrupt block on file '/opt/app/oracle/product/19.x.0/dbhome_1/dbs/spfilemasterdr.ora' blockno=1
Reread resulted in same corrupt block on file '/opt/app/oracle/product/19.x.0/dbhome_1/dbs/spfilemasterdr.ora' blockno=1

The error keeps repeating and no going forward from this point.

The solution was to move the DB spfile out of ASM into local disk ($ORACLE_HOME/dbs) and re-run the duplicate command. There were no issue in the subsequent execution.

Related Post
4K Sector, compatible.rdbms and Redo Log File Block Size

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

}