Saturday, March 1, 2014

Session Cached Cursors and JDBC CallableStatement

Similar to earlier post that compared the various preparedstatments scenarios this post examine the use of callablestatements and the effects of session cached cursors (SCC) parameter. Case 1 and Case 2 are same as with the preparedstatements.

Case 1VsCase 2
Create CallableStatement
  For Loop
    bind values
    execute
  End Loop
Close CallableStatement
For Loop
  Create CallableStatement
  bind values
  execute
  Close CallableStatement
End Loop

However the execution of client side code via JDBC results in two calls, one from the JDBC calling the PL/SQL and other the SQL within the PL/SQL. First up is the case 1 with SCC=50 where the callablestatment is executed 10000 times. Output format is same as earlier.The java code and the pl/sql scripts used for the test is given at the end of the post.
start got connection
1 select rownum,sql_text,cursor_type,USER_NAME,sid from v$open   OPEN                             ASANGA 19
2 select /*+ connect_by_filtering */ privilege#,level from sys   SESSION CURSOR CACHED            SYS    19
3 insert into sys.aud$( sessionid,entryid,statement,ntimestamp   OPEN-RECURSIVE                   ASANGA 19
4 select value$ from props$ where name = 'GLOBAL_DB_NAME'        DICTIONARY LOOKUP CURSOR CACHED  SYS    19
5 select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_CONTEXT('U   DICTIONARY LOOKUP CURSOR CACHED  SYS    19
6 select decode(failover_method, NULL, 0 , 'BASIC', 1, 'PRECON   DICTIONARY LOOKUP CURSOR CACHED  SYS    19
7 select privilege# from sysauth$ where (grantee#=:1 or grante   DICTIONARY LOOKUP CURSOR CACHED  SYS    19

Parse_Total Hard_Parse Ses_Cur_Cache_Hit Ses_Cur_Cache_Count CPU
        9         0         3                 7               3

end got connection

start execute
1 SELECT B FROM X WHERE A = :B1                                 PL/SQL CURSOR CACHED              ASANGA 19
2 begin :1  := cursorfunc(:2 ); end;                            DICTIONARY LOOKUP CURSOR CACHED   ASANGA 19
3 select rownum,sql_text,cursor_type,USER_NAME,sid from v$open  DICTIONARY LOOKUP CURSOR CACHED   ASANGA 19
4 select * from (SELECT name,  value FROM v$sesstat,  v$statna  DICTIONARY LOOKUP CURSOR CACHED   ASANGA 19
5 select /*+ connect_by_filtering */ privilege#,level from sys  SESSION CURSOR CACHED             SYS    19
6 insert into sys.aud$( sessionid,entryid,statement,ntimestamp  OPEN-RECURSIVE                    ASANGA 19
7 select value$ from props$ where name = 'GLOBAL_DB_NAME'       DICTIONARY LOOKUP CURSOR CACHED   SYS    19
8 select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_CONTEXT('U  DICTIONARY LOOKUP CURSOR CACHED   SYS    19
9 select decode(failover_method, NULL, 0 , 'BASIC', 1, 'PRECON  DICTIONARY LOOKUP CURSOR CACHED   SYS    19
10 select privilege# from sysauth$ where (grantee#=:1 or grante DICTIONARY LOOKUP CURSOR CACHED   SYS    19

Parse_Total Hard_Parse Ses_Cur_Cache_Hit Ses_Cur_Cache_Count CPU
        11         0         10004                 10        587
end execute
At the time of the connection get the connection (session) has done 9 parses in total and already had 3 session cache hits and 7 cursors cached and spent 3 centi-seconds of CPU. After the execute of the callablestatement the output shows that two additional (soft) parses occurred and 10001 session cache hits. Since the callablestatement is never closed as such it's never cached and the 10001 cache hits occurred due to the SQL called inside the PL/SQL function (1 in second output above). when the PL/SQL called for the first time the SQL inside it will be missing from the session cache. At the completion of the PL/SQL this cursor is implicitly closed (even though java side callablestatement is never closed) resulting it being added to the session cache and being found on subsequent executions from the same connection. This result in 9999 session cache hits. The other two are statistics gathering SQLs that were executed second time around.
Tkprof formatted output shows the following for this case.
begin :1  := cursorfunc(:2 ); end;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  10000      2.89       3.23          0          6          0       10000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    10001      2.89       3.23          0          6          0       10000

SELECT B FROM X WHERE A = :B1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  10000      0.28       0.39          0          0          0           0
Fetch    10000      0.66       0.75          0      60000          0       10000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    20001      0.95       1.14          0      60000          0       10000
Both SQL and callablestatement were parsed once and executed multiple times. The CPU usage for this case is 584 centi-seconds.
Next is the case 2 with SCC=50, output given below.
start got connection

1 select rownum,sql_text,cursor_type,USER_NAME,sid from v$open  OPEN                             ASANGA  19
2 select /*+ connect_by_filtering */ privilege#,level from sys  SESSION CURSOR CACHED            SYS     19
3 insert into sys.aud$( sessionid,entryid,statement,ntimestamp  OPEN-RECURSIVE                   ASANGA  19
4 select value$ from props$ where name = 'GLOBAL_DB_NAME'       DICTIONARY LOOKUP CURSOR CACHED  SYS     19
5 select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_CONTEXT('U  DICTIONARY LOOKUP CURSOR CACHED  SYS     19
6 select decode(failover_method, NULL, 0 , 'BASIC', 1, 'PRECON  DICTIONARY LOOKUP CURSOR CACHED  SYS     19
7 select privilege# from sysauth$ where (grantee#=:1 or grante  DICTIONARY LOOKUP CURSOR CACHED  SYS     19

Parse_Total Hard_Parse Ses_Cur_Cache_Hit Ses_Cur_Cache_Count CPU
        9         0         3                 7               2

end got connection

start execute
1 SELECT B FROM X WHERE A = :B1                                 PL/SQL CURSOR CACHED             ASANGA  19
2 begin :1  := cursorfunc(:2 ); end;                            SESSION CURSOR CACHED            ASANGA  19
3 select rownum,sql_text,cursor_type,USER_NAME,sid from v$open  DICTIONARY LOOKUP CURSOR CACHED  ASANGA  19
4 select * from (SELECT name,  value FROM v$sesstat,  v$statna  DICTIONARY LOOKUP CURSOR CACHED  ASANGA  19
5 select /*+ connect_by_filtering */ privilege#,level from sys  SESSION CURSOR CACHED            SYS     19
6 insert into sys.aud$( sessionid,entryid,statement,ntimestamp  OPEN-RECURSIVE                   ASANGA  19
7 select value$ from props$ where name = 'GLOBAL_DB_NAME'       DICTIONARY LOOKUP CURSOR CACHED  SYS     19
8 select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_CONTEXT('U  DICTIONARY LOOKUP CURSOR CACHED  SYS     19
9 select decode(failover_method, NULL, 0 , 'BASIC', 1, 'PRECON  DICTIONARY LOOKUP CURSOR CACHED  SYS     19
10 select privilege# from sysauth$ where (grantee#=:1 or grante DICTIONARY LOOKUP CURSOR CACHED  SYS     19

Parse_Total Hard_Parse Ses_Cur_Cache_Hit Ses_Cur_Cache_Count CPU
        11         0         20003                 10        721

end execute
The case 2 test result in two additional soft parses after the callablestatement is executed. But the total session cache hit is 20000. Since the callable statement is repeatedly created with each iteration this results in 9999 session cache hits plus the 9999 from the SQL inside the PL/SQL function which is 19998 together with the two cache hits for the statistics gathering sql makes it 20000 session cache hits. Total CPU used is 719 centi-seconds, higher compared to case 1. Tkprof formatted output shows the following, trace file incorrectly list 10000 parses for callablestatement (same as in the case of preparedstatements)
begin :1  := cursorfunc(:2 ); end;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    10000      0.23       0.30          0          0          0           0
Execute  10000      3.08       3.15          0          6          0       10000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    20000      3.31       3.45          0          6          0       10000

SELECT B FROM X WHERE A = :B1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  10000      0.38       0.39          0          0          0           0
Fetch    10000      0.63       0.72          0      60000          0       10000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    20001      1.02       1.12          0      60000          0       10000




In the second phase the same two test cases carried out but with session cached cursors parameter set to 0. Below is the output from case 1 with SCC=0
start got connection

1 select rownum,sql_text,cursor_type,USER_NAME,sid from v$open OPEN           ASANGA 151
2 insert into sys.aud$( sessionid,entryid,statement,ntimestamp OPEN-RECURSIVE ASANGA 151

Parse_Total Hard_Parse Ses_Cur_Cache_Hit Ses_Cur_Cache_Count CPU
        12         0         0                 0               6

end got connection

start execute
1 select rownum,sql_text,cursor_type,USER_NAME,sid from v$open OPEN           ASANGA 151
2 insert into sys.aud$( sessionid,entryid,statement,ntimestamp OPEN-RECURSIVE ASANGA 151

Parse_Total Hard_Parse Ses_Cur_Cache_Hit Ses_Cur_Cache_Count CPU
        10015         0         0                 0          717
end execute
As there's no session cached cursors the execution of callablestatement resulted in 10003 soft parses. This count is made up of 10000 soft parses on the SQL inside the PL/SQL, one soft parse on the callablestatement and the two statistics gathering statements. In this case repeated use of the open callablestatement does not result in additional parses. The tkprof output confirm is given below
begin :1  := cursorfunc(:2 ); end;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  10000      4.16       4.32          0          6          0       10000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    10001      4.16       4.32          0          6          0       10000

SELECT B FROM X WHERE A = :B1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    10000      0.24       0.31          0          0          0           0
Execute  10000      0.32       0.46          0          0          0           0
Fetch    10000      0.59       0.73          0      60000          0       10000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    30000      1.17       1.50          0      60000          0       10000
Output of the case 2 is given below.
start got connection

1 select rownum,sql_text,cursor_type,USER_NAME,sid from v$open OPEN           ASANGA 139
2 insert into sys.aud$( sessionid,entryid,statement,ntimestamp OPEN-RECURSIVE ASANGA 139

Parse_Total Hard_Parse Ses_Cur_Cache_Hit Ses_Cur_Cache_Count CPU
        12         0         0                 0               5

end got connection

start execute
1 select rownum,sql_text,cursor_type,USER_NAME,sid from v$open OPEN           ASANGA 139
2 insert into sys.aud$( sessionid,entryid,statement,ntimestamp OPEN-RECURSIVE ASANGA 139

Parse_Total Hard_Parse Ses_Cur_Cache_Hit Ses_Cur_Cache_Count CPU
        20014         0         0                 0          945

end execute
Since callablestatement is closed after each iteration, this results in soft parses each time its called. Therefore in this case the total number of soft parses are 20002. This count is made up of 10000 soft parses for callablestatement, 10000 for the SQL inside PL/SQL and the two statistics gathering SQLs. The tkprof output also list the soft parses
begin :1  := cursorfunc(:2 ); end;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    10000      0.37       0.41          0          0          0           0
Execute  10000      4.45       4.48          0          6          0       10000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    20000      4.83       4.90          0          6          0       10000

SELECT B FROM X WHERE A = :B1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    10000      0.30       0.32          0          0          0           0
Execute  10000      0.40       0.50          0          0          0           0
Fetch    10000      0.69       0.75          0      60000          0       10000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    30000      1.40       1.58          0      60000          0       10000
As with the preparedstatment, it is possible to reduce some of the soft parses when SCC=0 by enabling cursor caching on the connection pool or connection. The output of these tests are not shown but the parse count and CPU is included in the summary table.
TestParse countCPU (centi-seconds)
SCC=50,Case=1,MaxStm=02584
SCC=50,Case=2,MaxStm=02719
SCC=0,Case=1,MaxStm=010003711
SCC=0,Case=2,MaxStm=020002940
SCC=0,Case=1,MaxStm=1010001724
SCC=0,Case=2,MaxStm=1010001731

CPU usage graph for each case.

These tests have shown setting SCC is helpful in reducing the parse count and the CPU usage associated with parsing. When SCC is not set or cannot be set, similar behavior could be achieved with by setting cursor caching on connection pool.

Related Post
Session Cached Cursors and JDBC PreparedStatement

Database test case Code
create table x (a number, b varchar2(10));

begin
  for i in 1 .. 10
  loop
  insert into x values (i, 'abc'||i);
  end loop;
end;
/

create or replace function cursorfunc(inval in number) 
return varchar2 as
  retval varchar2(10);
begin
  select b into retval from x where a = inval;
  return retval;
end;
/
Java Code
import java.sql.CallableStatement;
import java.sql.Connection;
import java.sql.PreparedStatement;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.util.logging.Level;
import java.util.logging.Logger;

import oracle.ucp.jdbc.PoolDataSource;
import oracle.ucp.jdbc.PoolDataSourceFactory;

/**
 *
 * @author Asanga
 */
public class PLSQLCursorTest {

    static String SQL1 = "begin ? := cursorfunc(?); end;";

    static String SQL2 = "select * from (SELECT name,  value FROM v$sesstat,  v$statname WHERE v$sesstat.statistic#=v$statname.statistic# "
            + "AND (v$statname.name in ('parse count (total)','parse count (hard)','session cursor cache hits','session cursor cache count','CPU used by this session'))"
            + " AND v$sesstat.sid= sys_context('USERENV','SID')"
            + " )pivot (sum(value) for name in ('parse count (total)' as Parse_Total,'parse count (hard)' Hard_Parse,'session cursor cache hits' as SES_CUR_CACHE_HITS,'session cursor cache count' as SES_CUR_CACHE_COUNT, 'CPU used by this session' as CPU))";
    static String SQL3 = "select rownum,sql_text,cursor_type,USER_NAME,sid from v$open_cursor where sid=sys_context('USERENV','SID')";


    public static void main(String[] args) throws Exception {
        try {

            PoolDataSource ds = PoolDataSourceFactory.getPoolDataSource();
            ds.setConnectionFactoryClassName("oracle.jdbc.pool.OracleDataSource");
            ds.setConnectionPoolName("TTPool");
            ds.setURL("jdbc:oracle:thin:@192.168.0.85:1521/dbsrv1");
            ds.setUser("asanga");
            ds.setPassword("asa");
//            ds.setMaxStatements(10);

            Connection con = ds.getConnection();
            CallableStatement pr = null;

            System.out.println("start got connection");
            stat(con);
            System.out.println("end got connection");

            System.out.println("start execute");

/****************************** Start CASE 1 ************************************/
//            pr = con.prepareCall(SQL1);
//            pr.registerOutParameter(1, java.sql.Types.VARCHAR);
//            for (int i = 0; i < 10000; i++) {
//                pr.setInt(2,(i%10)+1 );
//                pr.execute();
//                pr.getString(1);
//            }
//
//            pr.close();
/****************************** End CASE 1 ************************************/

/****************************** Start CASE 2 ************************************/
            for (int i = 0; i < 10000; i++) {
                pr = con.prepareCall(SQL1);
                pr.registerOutParameter(1, java.sql.Types.VARCHAR);
                pr.setInt(2, (i%10)+1);
                pr.execute();
                pr.getString(1);
                pr.close();
            }
            pr.close();
/****************************** End CASE 2 ************************************/

            stat(con);
            System.out.println("end execute");
            con.close();

        } catch (SQLException ex) {
            Logger.getLogger(PLSQLCursorTest.class.getName()).log(Level.SEVERE, null, ex);
        }


    }

    public static void stat(Connection con) throws SQLException {

        PreparedStatement pr = null;
        ResultSet rs = null;

        pr = con.prepareStatement(SQL3);
        rs = pr.executeQuery();
        while (rs.next()) {
            System.out.println(rs.getString(1) + " " + rs.getString(2) + " " + rs.getString(3) + " " + rs.getString(4) + " " + rs.getString(5));
        }

        rs.close();
        pr.close();

        System.out.println("Parse_Total Hard_Parse Ses_Cur_Cache_Hit Ses_Cur_Cache_Count CPU");
        pr = con.prepareStatement(SQL2);
        rs = pr.executeQuery();

        while (rs.next()) {

            System.out.println("\t" + rs.getString(1) + "\t " + rs.getInt(2) + "\t " + rs.getString(3) + "\t\t " + rs.getInt(4)+ "\t       " + rs.getInt(5));
        }

        rs.close();
        pr.close();

    }
}

Session Cached Cursors and JDBC PreparedStatement