Categories
Blog Posts

Example of resetting user session handle attributes in JDBC

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.

Leave a Reply

This site uses Akismet to reduce spam. Learn how your comment data is processed.

%d bloggers like this: