Earlier, Mark Williams showed us how in Java to clear the session handle attributes to enable our code to be more easily traced. Because I had not seen the trace data produced when using his method, I decided to construct a test to see the trace data produced when the code does and does not execute the Connection.isValid method.
Here is the code that I used in my test:
/*
* javac -cp $ORACLE_HOME/jdbc/lib/ojdbc6.jar test.java
*/
import java.sql.*;
public class test {
public static void main (String args[]) throws SQLException, Exception {
String username = args[0];
String passwd = args[1];
String jdbcurl = args[2];
boolean doIsValid = args.length > 3 && args[3].contentEquals("isValid");
Connection c = DriverManager.getConnection(jdbcurl, username, passwd);
PreparedStatement s;
ResultSet rs;
c.setClientInfo("OCSID.CLIENTID", "tester");
c.setClientInfo("OCSID.MODULE", "testmodule");
c.setClientInfo("OCSID.ACTION", "testaction");
// First and last statement in testmodule-testaction
s = c.prepareStatement("select 1 from dual");
rs = s.executeQuery();
rs.next();
c.setClientInfo("OCSID.CLIENTID", null);
c.setClientInfo("OCSID.MODULE", null);
c.setClientInfo("OCSID.ACTION", null);
if (doIsValid) {
System.out.println("calling isValid");
c.isValid(0); // a forced round trip
} else {
System.out.println("not calling isValid");
}
// Mimic what might happen if a pooled session isn't reused for a while
try {
Thread.sleep(5000);
} catch (Throwable ex) {
}
// First statement in the subsequently executed application, but not traced
s = c.prepareStatement("select 2 from dual");
rs = s.executeQuery();
rs.next();
c.close();
}
}I execute this to create a standing order for tracing the application:
SQL> exec dbms_monitor.serv_mod_act_trace_enable('SYS$USERS', 'testmodule', 'testaction', true, false , 'or12', 'all_executions')When I execute the code like this:
$ java -cp $ORACLE_HOME/jdbc/lib/ojdbc6.jar:. test scott tiger jdbc:oracle:thin:@oradb0:1521:or12
Then I get a trace file that looks like this:
… *** 2020-08-04 11:41:41.069 *** SESSION ID:(1.11921) 2020-08-04 11:41:41.069 *** CLIENT ID:(tester) 2020-08-04 11:41:41.069 *** SERVICE NAME:(SYS$USERS) 2020-08-04 11:41:41.069 *** MODULE NAME:(testmodule) 2020-08-04 11:41:41.069 *** CLIENT DRIVER:(jdbcthin) 2020-08-04 11:41:41.069 *** ACTION NAME:(testaction) 2020-08-04 11:41:41.069 ===================== PARSING IN CURSOR #140313188499360 len=18 dep=0 uid=110 oct=3 lid=110 tim=3556315385 hv=2866845384 ad='6f1ee6a8' sqlid='520mkxqpf15q8' select 1 from dual END OF STMT PARSE #140313188499360:c=78,e=118,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=3556315381 EXEC #140313188499360:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=3556315706 WAIT #140313188499360: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3556315739 FETCH #140313188499360:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=3556315761 STAT #140313188499360 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=2 us cost=2 size=0 card=1)' *** 2020-08-04 11:41:46.131 WAIT #140313188499360: nam='SQL*Net message from client' ela= 5062332 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3561378158
When I execute the code like this:
$ java -cp $ORACLE_HOME/jdbc/lib/ojdbc6.jar:. test scott tiger jdbc:oracle:thin:@oradb0:1521:or12 isValid
Then I get a trace file that looks like this:
… *** 2020-08-04 11:42:16.069 *** SESSION ID:(1.51525) 2020-08-04 11:42:16.069 *** CLIENT ID:(tester) 2020-08-04 11:42:16.069 *** SERVICE NAME:(SYS$USERS) 2020-08-04 11:42:16.069 *** MODULE NAME:(testmodule) 2020-08-04 11:42:16.069 *** CLIENT DRIVER:(jdbcthin) 2020-08-04 11:42:16.069 *** ACTION NAME:(testaction) 2020-08-04 11:42:16.069 ===================== PARSING IN CURSOR #140199631364000 len=18 dep=0 uid=110 oct=3 lid=110 tim=3591315945 hv=2866845384 ad='6f1ee6a8' sqlid='520mkxqpf15q8' select 1 from dual END OF STMT PARSE #140199631364000:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=3591315942 EXEC #140199631364000:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=3591316310 WAIT #140199631364000: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3591316342 FETCH #140199631364000:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=3591316364 STAT #140199631364000 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=2 us cost=2 size=0 card=1)' *** 2020-08-04 11:42:16.137 WAIT #140199631364000: nam='SQL*Net message from client' ela= 67201 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3591383631
The final line in both files reveal a significant difference in time going to SQL*Net message from client.
If your application executes the Connection.isValid method, you do get an extra round-trip to the database server but the amount of time attributed to it will probably be a short time interval whose value varies only a little bit, especially if you are careful about managing your application workload.
But if your application doesn’t then the amount of time attributed to it might not be predictable at all. In fact, it would vary depending upon the frequency of incoming transactions and the session-to-application assignment algorithm employed by the connection pool software.
Because I wanted to believe we could avoid an additional round-trip between the application server and the database server, I was hoping my test would reveal the execution of Connection.isValid is not required. But I’m convinced that it is required and I expect the cost of the extra round-trip to be worthwhile.