Martins Blog

Trying to explain complex things in simple terms

Getting up and running with Universal Connection Pool – Take 2

Posted by Martin Bach on February 4, 2011

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!

2 Responses to “Getting up and running with Universal Connection Pool – Take 2”

  1. […] up FCF with UCP outside of the Oracle documentation is this blog post by Martin Bach and its take 2. I have to thank Martin for publishing his work as without it I wouldn’t have been in a […]

  2. […] to repeat all the details about setting up Tomcat for use with UCP, please refer to part 1 and part 2 for the basics. The following example also uses the sample web […]

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

 
%d bloggers like this: