Getting up and running with Universal Connection Pool – Take 2

In yesterday’s post (which is actually didn’t want to post that day) I wrote about the Universal Connection Pool feature. You should be able to get started with the information I gave you, but it didn’t include any hints on how to have a look under the covers of UCP. This can be changed …Oracle includes very fine-grained logging information with UCP, but experiment show that you have to either use log level FINE or FINEST to get to the real information of what’s going on.

LOGGING

Tomcat uses the log4j framework to define its own logging, as shown in the catalina.{bat,sh} file:

set LOGGING_CONFIG=-Djava.util.logging.config.file=”%CATALINA_BASE%\conf\logging.properties”

One thing you possibly don’t want to do is to include your own log4j configuration there-any change to your application’s file requires a restart of tomcat. Think of a production environment and then it becomes clear why such an approach is neither desirable nor practical.

Instead, you can put a file called logging.properties into the src directory within your application. In it you define logging to your heart’s delight. I have taken the following from the documentation and Pas Apicella’s blog. It really opens the floodgates for very detailed logging, so don’t use this in any other than a development environment…

handlers = org.apache.juli.FileHandler, java.util.logging.ConsoleHandler

org.apache.juli.FileHandler.level = ALL
org.apache.juli.FileHandler.directory = ${catalina.base}/logs
org.apache.juli.FileHandler.prefix = ucp.
org.apache.juli.FileHandler.formatter = oracle.ucp.util.logging.UCPFormatter

java.util.logging.FileHandler.level = WARNING

.level = FINEST

# FCF classes
oracle.ucp.common.FailoverEventHandlerThreadBase.level = ALL

oracle.ucp.jdbc.oracle.ONSDatabaseFailoverEvent.level = ALL
oracle.ucp.jdbc.oracle.ONSRuntimeLBEventHandlerThread.level = ALL
oracle.ucp.jdbc.oracle.ONSOracleRuntimeLBEventSubscriber.level = ALL
oracle.ucp.jdbc.oracle.ONSRuntimeLoadBalancingEvent.level = ALL
oracle.ucp.jdbc.oracle.ONSOracleFailoverEventSubscriber.level = ALL
oracle.ucp.jdbc.oracle.ONSDatabaseEventHandlerThread.level = ALL
oracle.ucp.jdbc.oracle.OracleFailoverEvent.level = ALL
oracle.ucp.jdbc.oracle.OracleFailoverEventSubscriber.level = ALL
oracle.ucp.jdbc.oracle.OracleFailoverEventImpl.level = ALL
oracle.ucp.jdbc.oracle.OracleFailoverEventNotification.level = ALL
oracle.ucp.jdbc.oracle.OracleFailoverHandler.level = ALL
oracle.ucp.jdbc.oracle.OracleFailoverablePooledConnection.level = ALL

oracle.ucp.jdbc.oracle.OraclePooledConnectionConnectionPool.level = ALL
oracle.ucp.jdbc.oracle.OracleConnectionConnectionPool.level = ALL
oracle.ucp.jdbc.oracle.OracleXAConnectionConnectionPool.level = ALL
oracle.ucp.jdbc.oracle.OracleJDBCConnectionPool.level = ALL

oracle.ucp.jdbc.oracle.OracleDatabaseInstanceInfo.level = ALL
oracle.ucp.jdbc.oracle.OracleDatabaseInstanceInfoList.level = ALL

# RCLB classes
oracle.ucp.jdbc.oracle.ONSRuntimeLBEventHandlerThread.level = ALL
oracle.ucp.jdbc.oracle.ONSOracleRuntimeLBEventSubscriber.level = ALL
oracle.ucp.jdbc.oracle.OracleRuntimeLoadBalancingHandler.level = ALL
oracle.ucp.jdbc.oracle.ONSRuntimeLoadBalancingEvent.level = ALL

Now when you redeploy your application, a new file ucp.timestamp will be created in %CATALINA_HOME%\logs and list all the beauty of what’s going on. The log file is now very verbose though.

FAST CONNECTION FAILOVER

The previous source code didn’t take full potential of the fact that the fastConnectionFailover functionality was enabled. For the following to work you might want to disable the validateConnectionOnBorrow setting in META-INF/context.xml. In fact, we’d like to validate the connection when we get it from the pool ourselves. The code of the Hello.java servlet has changed as follows:

// time to get UCP to start
writer.println("
<h1> UCP</h1>
");
Connection conn = null;
oracle.ucp.jdbc.PoolDataSource ds = null;
try {
Context ctx = new InitialContext();
Context envContext = (Context) ctx.lookup("java:/comp/env");

ds = (oracle.ucp.jdbc.PoolDataSource) envContext.lookup ("jdbc/UCPPool");

writer.println("Got the datasource - ");
writer.println("FCF enabled? " + ds.getFastConnectionFailoverEnabled());

conn = ds.getConnection();
} catch (Exception e) {
try {
// here's where the FCF comes in
if (conn == null || !((ValidConnection) conn).isValid()) {
writer.println("<p>Have to retry connection (" + e.getMessage() + ")</p>");
OracleJDBCConnectionPoolStatistics stats =
(OracleJDBCConnectionPoolStatistics) ds.getStatistics();
writer.println("Pool stats: " + stats.getFCFProcessingInfo());
conn.close();
} else {
writer.println("Unknown exception: " + e);
}
} catch (SQLException sqle) {
e.printStackTrace();
return;
}
}

try {
writer.println("<p>Connected to Oracle intance</P> ");

Statement stmt = conn.createStatement();
ResultSet rs = stmt.executeQuery("select 'Hello World from '||sys_context('userenv','instance_name') from dual");
while (rs.next()) {
writer.println("<p><pre>" + rs.getString(1) + "</pre></p>");
}

rs.close();
stmt.close();
conn.close();

} catch (Exception e) {
writer.println("<pre>" + e + "</pre>");
}

writer.println("</body>");
writer.println("</html>");

}

I will probably attach the code to the post as the layout is pretty broken.

IS THE POOL INTELLIGENT?

To see if the runtime load balancing feature works at all I shut down the second of my two database instances before restarting the application. I expect all sessions to be on the first instance (to be expected as there is not a second one). Is that so?

SQL> ed
Wrote file afiedt.buf

 1  select count(inst_id),inst_id,
 2  status from gv$session where username='SCOTT'
 3* group by inst_id, status
SQL> /
COUNT(INST_ID)    INST_ID STATUS
-------------- ---------- --------
58          1 INACTIVE

Now what happens when I start the second instance?

SQL> !srvctl start instance -d lnrut1d -i LNRUT1D_2
/

SQL>
COUNT(INST_ID)    INST_ID STATUS
-------------- ---------- --------
 69          1 INACTIVE

SQL> /

COUNT(INST_ID)    INST_ID STATUS
-------------- ---------- --------
 57          1 INACTIVE
 19          2 INACTIVE

SQL> /

COUNT(INST_ID)    INST_ID STATUS
-------------- ---------- --------
 25          1 INACTIVE
 45          2 INACTIVE

That’s neat-the second instance catches up. I eventually ended up near-equilibrium. The inverse is also true. Consider two instances up as shown here:

SQL> select count(inst_id),inst_id,
 2  status from gv$session where username='SCOTT'
 3  group by inst_id, status
 4  /

COUNT(INST_ID)    INST_ID STATUS
-------------- ---------- --------
 21          1 INACTIVE
 26          2 INACTIVE
 1          2 ACTIVE
 2          1 ACTIVE

SQL> !srvctl stop instance -d lnrut1d -i LNRUT1D_2 -o abort

SQL> /

COUNT(INST_ID)    INST_ID STATUS
-------------- ---------- --------
 36          1 INACTIVE

Now when I shut the second instance down, the number of sessions on the first node goes up:

SQL> /

COUNT(INST_ID)    INST_ID STATUS
-------------- ---------- --------
 65          1 INACTIVE

 

I like this!