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 1 | Vs | Case 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 executeAt 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 executeThe 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 executeAs 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 executeSince 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.
| Test | Parse count | CPU (centi-seconds) |
|---|
| SCC=50,Case=1,MaxStm=0 | 2 | 584 |
| SCC=50,Case=2,MaxStm=0 | 2 | 719 |
| SCC=0,Case=1,MaxStm=0 | 10003 | 711 |
| SCC=0,Case=2,MaxStm=0 | 20002 | 940 |
| SCC=0,Case=1,MaxStm=10 | 10001 | 724 |
| SCC=0,Case=2,MaxStm=10 | 10001 | 731 |
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
