Tuesday, March 18, 2014

Oracle vs Standard JDBC Batching For Updates

Oracle provided two flavors of batching with the JDBC drivers. One was called standard which followed the JBDC 2.0 specification and the other flavor was an Oracle specific implementation (called Oracle Batching) which is independent of JDBC 2.0. It is not possible to mix both these modes in the same application. However with the latest implementation of the JDBC driver (12c) Oracle update batching is depreciated. Evolution of the documentation over the years on this is given below.
From 10.2 JDBC developers guide Oracle update batching is a more efficient model because the driver knows ahead of time how many operations will be batched. In this sense, the Oracle model is more static and predictable. With the standard model, the driver has no way of knowing in advance how many operations will be batched. In this sense, the standard model is more dynamic in nature.
From 11.2 JDBC developers guide Oracle recommends that you use JDBC standard features when possible. This recommendation applies to update batching as well. Oracle update batching is retained primarily for backwards compatibility.
From 12.1 JDBC developers guide Starting from Oracle Database 12c Release 1 (12.1), Oracle update batching is deprecated. Oracle recommends that you use standard JDBC batching instead of Oracle update batching.
As the Oracle mode batching is depreciated the comparison only holds for lower versions of the JDBC drivers. The test related to this post was carried out using 11.2 JDBC driver. The java code used for the test is given at the end of the post. Two tests were carried out. First involving updating number of rows in a table with standard, standard implementation of oracle batching and oracle batching. Standard batching test only execute the update batch once. The standard implementation mimics what the Oracle standard does by executing the update batch at fixed intervals (500 and 1000 updates at a time). Finally Oracle batching will use the values of 500 and 1000 for batch values. This test is to check if there's any considerable difference in the timing of the updates. Result table is given below.
# UpdatesStandared BatchingStandared Batching - 500Standared Batching - 1000Oracle Batching - 500Oracle Batchnig - 1000
1000.350.350.360.360.36
2000.620.620.650.630.63
5001.431.411.471.431.45
10002.762.732.882.812.81
20005.725.385.645.545.68
500013.5513.4313.9913.6713.79
1000027.8226.5828.0527.3127.58
2500080.0175.4378.6576.4276.93
50000165.24158.99164.32159.13159.04
75000243.25242.92248.73242.17242.79
100000330.92330.84333.34327.65331.22

There's not much difference in terms of time it takes to complete all the updates whether it is via standard batching or oracle batching. Scatter plot shown below.




The next test involved updating a column with a blob (size 8KB). The results table is given below.
# UpdatesStandared BatchingStandared Batching - 500Standared Batching - 1000Oracle Batching - 500Oracle Batchnig - 1000
1001.471.531.501.681.76
2002.792.962.913.143.19
5006.887.377.147.687.87
100013.6014.7014.2015.3015.50
200027.3129.2530.1330.0730.41
500068.3074.1074.8977.2374.82
10000143.31151.05143.14151.68152.43
25000348.83351.34365.54384.77394.99
50000701.67727.28707.79857.79859.15

There's not much difference in the update time between the different standard batching tests.

However there's some advantage when using standard batching compared to oracle standard as the number of updates are 25,000 or over. But the increase number of batching size requires more memory and this situation may be uncommon. For lower values again there's not much difference in terms of time saved.

These tests have shown that batching mode (Oracle or standard) does not have a real influence on the time taken for the updates. As mentioned earlier as of 12c the Oracle standard batching is depreciated and if these results hold true for 12c driver as well then there shouldn't be any performance degradation.

Test java code used
import java.sql.Connection;
import java.sql.PreparedStatement;
import java.sql.SQLException;
import java.util.logging.Level;
import java.util.logging.Logger;
import oracle.jdbc.pool.OracleDataSource;

/**
 *
 * @author Asanga
 */
public class Update {
    
    public static void main(String[] args) {
        try {
            OracleDataSource dataSource = new OracleDataSource();
               dataSource.setURL("jdbc:oracle:thin:@192.168.0.66:1521:ent11g2");
               dataSource.setUser("asanga");
               dataSource.setPassword("asa");               
               
//               String SQL = "update x set b = ?, c = ? where a = ?"; // update blob
               String SQL = "update x set b = ? where a = ?";
               
               Connection con = dataSource.getConnection();
               con.setAutoCommit(false);
               
               long t1 = System.nanoTime();
               
//               byte[] lob = new byte[8*1024];
//               lob[10] =10;
//               lob[8000]=20;
               
               PreparedStatement pr = con.prepareStatement(SQL);
//               ((OraclePreparedStatement)pr).setExecuteBatch(1000);
               for(int i =1; i <= 75000; i++){
                   
                   StringBuilder b = new StringBuilder("khf").append(i);
                   
                   pr.setString(1, b.toString());
//                   pr.setBytes(2,lob );
                   pr.setInt(2, i);
                   
                   pr.addBatch();
                   
                   if((i > 0) && (i%1000 == 0)){
                       int[] ret =pr.executeBatch();
                       System.out.println(ret.length);
                   }
//                   pr.executeUpdate();
               }
               
               int[] ret = pr.executeBatch();
//               ((OraclePreparedStatement)pr).sendBatch();
               con.commit();
               long t2 = System.nanoTime();
               
               System.out.println("returned "+ret.length+" time : "+(t2-t1));
//               System.out.println("time : "+(t2-t1));
               
               pr.close();
               con.close();
               
        } catch (SQLException ex) {
            Logger.getLogger(Update.class.getName()).log(Level.SEVERE, null, ex);
        }
    }
}

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