Fast Connection Failover (FCF) – JDBC HA – part 4

Posted on , updated on by Yannick Jaquier
Oracle ,

Table of contents

Preamble

Fast Connection Failover (FCF) is almost the same as previous testing except that here the FAN feature is provided by the connection pool directly and so you do not require the simplefan.jar class anymore. Instead we are going to use the Universal Connection Pool (UCP) class implemented in ucp.jar file.

Fast Connection Failover (FCF) testing

Universal Connection Pool (UCP) for JDBC

If you dig a bit in Oracle documentation you can find below statement:

Starting from Oracle Database 11g Release 2 (11.2), implicit connection pool has been deprecated, and replaced with Universal Connection Pool (UCP) for JDBC. Oracle recommends that you take advantage of the new architecture, which is more powerful and offers better performance.

So obviously I will use UCP in my Fast Connection Failover (FCF) testing !

The complete reference of Java class is available at Oracle® Universal Connection Pool for JDBC Java API Reference.

You have also an Oracle UCP FAQ but at the time of writing this blog post the page is full of bugs with missing links…

As we have seen with FAN you need a service and ONS up and running on your RAC cluster !

Java testing code

In below example code FCF is activated using this command:

pds.setFastConnectionFailoverEnabled(true);

I am also logging in a separate log file all the UCP events like initialization, connections closed, connections borrowed and so on. This is done in below part of the script:

// Logging UCP events in a log file
Handler fh = new FileHandler("fcf01.log");
// Finally the UCPFormatter is not providing a so nice display
//fh.setFormatter(new UCPFormatter());
fh.setFormatter(new SimpleFormatter());
UniversalConnectionPoolManager mgr = UniversalConnectionPoolManagerImpl.getUniversalConnectionPoolManager();
mgr.setLogLevel(Level.FINE);
Logger log = Logger.getLogger("oracle.ucp");
log.setLevel(Level.FINE);
log.addHandler(fh);
// To avoid display on screen
log.setUseParentHandlers(false);

The Oracle Notification Service (ONS) part is a bit cumbersome in Oracle documentation. The easiest way to implement it is to rely on what they call automatic ONS and register to the service managed by Grid infrastructure. Investigating further I have seen that in my case (newest releases of product) it’s not even more mandatory to register with setONSConfiguration method:

For standalone Java applications, you must configure ONS using the setONSConfiguration method. However, if your application meets the following requirements, then you no longer need to call the setONSConfiguration method for enabling FCF:

  • Your application is using Oracle Database 12c Release 1 (12.1) UCP and Oracle RAC Database 12c Release 1 (12.1)
  • Your application does not require ONS wallet or keystore

Java testing code

Finally the complete code with as much comment as I can to explain each part. You need to add to your project (classpath) ojdbc8.jar, ons.jar and ucp.jar.

package fcf01;
 
import java.sql.Connection;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
import java.util.Locale;
import java.util.logging.FileHandler;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.Logger;
import java.util.logging.SimpleFormatter;
import oracle.ucp.admin.UniversalConnectionPoolManager;
import oracle.ucp.admin.UniversalConnectionPoolManagerImpl;
import oracle.ucp.jdbc.JDBCConnectionPoolStatistics;
import oracle.ucp.jdbc.PoolDataSource;
import oracle.ucp.jdbc.PoolDataSourceFactory;
import oracle.ucp.jdbc.ValidConnection;
 
public class fcf01 {
 
  // To restrict display versus System.out.println(stats);
  // String fcfInfo = (oracleJDBCConnectionPool)stats.getFCFProcessingInfo(); NOT WORKING at all !!
  private static void display_statistics(JDBCConnectionPoolStatistics stats) {
    System.out.println("AbandonedConnectionsCount: " + stats.getAbandonedConnectionsCount());
    System.out.println("AvailableConnectionsCount: " + stats.getAvailableConnectionsCount());
    System.out.println("AverageBorrowedConnectionsCount: " + stats.getAverageBorrowedConnectionsCount());
    System.out.println("AverageConnectionWaitTime: " + stats.getAverageConnectionWaitTime());
    System.out.println("BorrowedConnectionsCount: " + stats.getBorrowedConnectionsCount());
    System.out.println("ConnectionsClosedCount: " + stats.getConnectionsClosedCount());
    System.out.println("ConnectionsCreatedCount: " + stats.getConnectionsCreatedCount());
    System.out.println("RemainingPoolCapacityCount: " + stats.getRemainingPoolCapacityCount());
    System.out.println("TotalConnectionsCount: " + stats.getTotalConnectionsCount());
    System.out.println("getPeakConnectionsCount: " + stats.getPeakConnectionsCount());
    System.out.println("getPendingRequestsCount: " + stats.getPendingRequestsCount());
    System.out.println("getRemainingPoolCapacityCount: " + stats.getRemainingPoolCapacityCount());
  }
 
  public static void main(String[] args) throws Exception {
    PoolDataSource pds = PoolDataSourceFactory.getPoolDataSource();
    Connection connection1 = null;
    Statement statement1 = null;
    ResultSet resultset1 = null;
 
    // To have date format in English, my Windows desktop being in French :-)
    Locale.setDefault(new Locale("en"));
    pds.setConnectionFactoryClassName("oracle.jdbc.pool.OracleDataSource");
    pds.setUser("yjaquier");
    pds.setPassword("secure_password");
    // The RAC connection using SCAN name and HA service
    pds.setURL("jdbc:oracle:thin:@(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=rac-cluster-scan.domain.com)(PORT=1531))(CONNECT_DATA=(SERVICE_NAME=pdb1srv)))");
    pds.setConnectionPoolName("FCFPool");
 
    // Automatic ONS
    // pds.setONSConfiguration("nodes=server2.domain.com:6200,server3.domain.com:6200");
    // Pool sizing
    pds.setMinPoolSize(10);
    pds.setMaxPoolSize(20);
    pds.setInitialPoolSize(10);
    // Enable Fast Connection Failover
    pds.setFastConnectionFailoverEnabled(true);
 
    // Simple check to demonstrate one cool method
    System.out.println("FCF activated ?: " + pds.getFastConnectionFailoverEnabled());
 
    // Logging UCP events in a log file
    Handler fh = new FileHandler("fcf01.log");
    // Finally the UCPFormatter is not providing a so nice display
    //fh.setFormatter(new UCPFormatter());
    fh.setFormatter(new SimpleFormatter());
    UniversalConnectionPoolManager mgr = UniversalConnectionPoolManagerImpl.getUniversalConnectionPoolManager();
    mgr.setLogLevel(Level.FINE);
    Logger log = Logger.getLogger("oracle.ucp");
    log.setLevel(Level.FINE);
    log.addHandler(fh);
    // To avoid display on screen
    log.setUseParentHandlers(false);
 
    while (true)
    {
      try
      {
        System.out.println("Trying to obtain a new connection from pool ...");
        connection1 = pds.getConnection();
        System.out.println("Number of borrowed connections from the pool: " + pds.getBorrowedConnectionsCount());
        statement1 = connection1.createStatement();
        // The infinite loop awaiting RAC node down events
        while (true)
        {
          System.out.println("\nPool status at "+LocalDateTime.now().format(DateTimeFormatter.ofPattern("dd-MM-yyyy HH:mm:ss"))+": ");
          JDBCConnectionPoolStatistics stats = pds.getStatistics();
          display_statistics(stats);
          resultset1 = statement1.executeQuery("select sys_context('USERENV','SERVER_HOST') from dual");
          while (resultset1.next()) {
            System.out.println("\nWorking on " + resultset1.getString(1));
          }
          resultset1 = statement1.executeQuery("select gvi.host_name,count(*) from gv$session gvs,  gv$instance gvi where gvs.inst_id=gvi.inst_id "
              + "and gvs.username='YJAQUIER' and program='JDBC Thin Client' group by gvi.host_name order by gvi.host_name");
          while (resultset1.next()) {
            System.out.println(resultset1.getString(1) + ": " + resultset1.getString(2));
          }
          Thread.sleep(2000);
          resultset1.close();
        }
      }
      catch (SQLException sqlexc)
      {
        System.out.println("SQLException detected ...");
        // Recommended method to check if a borrowed connection is still usable after an SQL exception
        if (connection1 == null || !((ValidConnection) connection1).isValid())
        {
          System.out.println("Connection retry necessary ...");
          try
          {
            connection1.close();
          }
          catch (Exception closeExc)
          {
            System.out.println("Exception detected when closing connection:");
            closeExc.printStackTrace();
          }
        }
      }
    }
  }
}

While the Java application is running I have directly killed (kill command under Linux) the instance on where the connection has been borrowed.

When the application start I have an almost equally distributed pool:

fcf01
fcf01

After I have killed the instance where the connection was borrowed we need to borrow a new one:

fcf02
fcf02

Once a new connection from pool has been borrowed we can continue working, with no application failure by the way:

fcf03
fcf03

In meanwhile the pool is growing to reach requested minimum on surviving instance:

fcf04
fcf04

Once the killed instance as restarted (automatically managed by Grid infrastructure) the pool is rebalanced across all the instances:

fcf05
fcf05

The Java application log file I have generated is confirming what we have graphically seen:

Feb 28, 2018 12:28:46 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.admin.UniversalConnectionPoolManagerMBeanImpl:getUniversalConnectionPoolManagerMBean::Universal Connection Pool Manager MBean created
Feb 28, 2018 12:28:47 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.jdbc.PoolDataSourceImpl:createPoolWithDefaultProperties:oracle.ucp.jdbc.PoolDataSourceImpl@591f989e:Connection pool instance is created with default properties
Feb 28, 2018 12:28:47 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.jdbc.PoolDataSourceImpl:createPool:oracle.ucp.jdbc.PoolDataSourceImpl@591f989e:Connection pool instance is created
Feb 28, 2018 12:28:48 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Topology:enableFANHeuristically:oracle.ucp.common.UniversalConnectionPoolBase$4@5c671d7f:Heuristically determine whether to enable FAN
Feb 28, 2018 12:28:48 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Topology:enableFANHeuristically:oracle.ucp.common.UniversalConnectionPoolBase$4@5c671d7f:RAC/GDS 12.x, FAN is heuristically enabled
Feb 28, 2018 12:28:51 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.UniversalConnectionPoolBase:start:oracle.ucp.jdbc.oracle.OracleConnectionConnectionPool@5f2050f6:pool started
Feb 28, 2018 12:28:51 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.jdbc.PoolDataSourceImpl:startPool:oracle.ucp.jdbc.PoolDataSourceImpl@591f989e:connection pool is started
Feb 28, 2018 12:29:25 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:growing...
Feb 28, 2018 12:29:29 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.FailoverDriver$1:handleNotifications:oracle.ucp.common.FailoverDriver$1@5cada3dd:event processed, snapshot:[orcl_1,db=orcl,service=pdb1srv,host=server2:(activeCount:4,borrowedCount:1,active:true,aff=true,violating=false,id=1), orcl_2,db=orcl,service=pdb1srv,host=server3:(activeCount:0,borrowedCount:0,active:false,aff=true,violating=false,id=0)]
Feb 28, 2018 12:29:29 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.FailoverDriver$1:handleNotifications:oracle.ucp.common.FailoverDriver$1@5cada3dd:event processed, snapshot:[orcl_1,db=orcl,service=pdb1srv,host=server2:(activeCount:4,borrowedCount:1,active:true,aff=true,violating=false,id=1), orcl_2,db=orcl,service=pdb1srv,host=server3:(activeCount:0,borrowedCount:0,active:false,aff=true,violating=false,id=0)]
Feb 28, 2018 12:30:07 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:grew up 1 connection to reach the minimum
Feb 28, 2018 12:30:07 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:growing...
Feb 28, 2018 12:30:07 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:grew up 1 connection to reach the minimum
Feb 28, 2018 12:30:07 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:growing...
Feb 28, 2018 12:30:07 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:grew up 1 connection to reach the minimum
Feb 28, 2018 12:30:07 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:growing...
Feb 28, 2018 12:30:07 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:grew up 1 connection to reach the minimum
Feb 28, 2018 12:30:07 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:growing...
Feb 28, 2018 12:30:09 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:grew up 1 connection to reach the minimum
Feb 28, 2018 12:30:09 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:growing...
Feb 28, 2018 12:30:09 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:grew up 1 connection to reach the minimum
Feb 28, 2018 12:31:12 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:growing...
Feb 28, 2018 12:31:15 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.Core:adjustMinLimit:oracle.ucp.common.Core@34f7cfd9:grew up 1 connection to reach the minimum
Feb 28, 2018 12:31:23 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.FailoverDriver$1:handleNotifications:oracle.ucp.common.FailoverDriver$1@5cada3dd:event processed, snapshot:[orcl_1,db=orcl,service=pdb1srv,host=server2:(activeCount:5,borrowedCount:1,active:true,aff=true,violating=false,id=1), orcl_2,db=orcl,service=pdb1srv,host=server3:(activeCount:6,borrowedCount:0,active:true,aff=true,violating=false,id=0)]
Feb 28, 2018 12:31:23 PM oracle.ucp.logging.ClioSupport _log
FINE: oracle.ucp.common.FailoverDriver$1:handleNotifications:oracle.ucp.common.FailoverDriver$1@5cada3dd:event processed, snapshot:[orcl_1,db=orcl,service=pdb1srv,host=server2:(activeCount:5,borrowedCount:1,active:true,aff=true,violating=false,id=1), orcl_2,db=orcl,service=pdb1srv,host=server3:(activeCount:6,borrowedCount:0,active:true,aff=true,violating=false,id=0)]

References

About Post Author

Yannick Jaquier

administrator

Find more about me on social media.

See author's posts

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes:

<a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>