When dealing with the library cache / shared pool it’s always worth checking from time to time to see if a new version of Oracle has changed any of the statistics you rely on as indicators of potential problems. Today is also (coincidentally) a day when comments about “parses” and “parse calls” entered my field of vision from two different directions. I’ve tweeted out references to a couple of quirkly little posts I did some years ago about counting parse calls and what a parse call may entail, but I thought I’d finish the day off with a little demo of what the session cursor cache does for you when your client code issues parse calls.
There are two bit of information I want to highlight – activity in the library cache and a number that shows up in the session statistics. Here’s the code to get things going:
rem rem Script: 12c_session_cursor_cache.sql rem Author: Jonathan Lewis rem Dated: Apr 2019 rem rem Note: rem start_1.sql contains the one line rem select * from t1 where n1 = 0; rem create table t1 as select 99 n1 from dual ; execute dbms_stats.gather_table_stats(user,'t1') spool 12c_session_cursor_cache prompt ======================= prompt No session cursor cache prompt ======================= alter session set session_cached_cursors = 0; set serveroutput off set feedback off execute snap_libcache.start_snap execute snap_my_stats.start_snap execute snap_libcache.start_snap execute snap_my_stats.start_snap @start_1000 set feedback on set serveroutput on execute snap_my_stats.end_snap execute snap_libcache.end_snap prompt ============================ prompt Session cursor cache enabled prompt ============================ alter session set session_cached_cursors = 50; set serveroutput off set feedback off execute snap_libcache.start_snap execute snap_my_stats.start_snap execute snap_libcache.start_snap execute snap_my_stats.start_snap @start_1000 set feedback on set serveroutput on execute snap_my_stats.end_snap execute snap_libcache.end_snap spool off
I’ve made use of a couple of little utilities I wrote years ago to take snapshots of my session statistics and the library cache (v$librarycache) stats. I’ve also used my “repetition” framework to execute a basic query 1,000 times. The statement is a simple “select from t1 where n1 = 0”, chosen to return no rows.
The purpose of the whole script is to show you the effect of running exactly the same SQL statement many times – first with the session cursor cache disabled (session_cached_cursors = 0) then with the cache enabled at its default size.
Here are some results from an instance of 12.2.0.1 – which I’ve edited down by eliminating most of the single-digit numbers.
======================= No session cursor cache ======================= --------------------------------- Session stats - 23-Apr 17:41:06 Interval:- 4 seconds --------------------------------- Name Value ---- ----- Requests to/from client 1,002 opened cursors cumulative 1,034 user calls 2,005 session logical reads 9,115 non-idle wait count 1,014 session uga memory 65,488 db block gets 2,007 db block gets from cache 2,007 db block gets from cache (fastpath) 2,006 consistent gets 7,108 consistent gets from cache 7,108 consistent gets pin 7,061 consistent gets pin (fastpath) 7,061 logical read bytes from cache 74,670,080 calls to kcmgcs 5,005 calls to get snapshot scn: kcmgss 1,039 no work - consistent read gets 1,060 table scans (short tables) 1,000 table scan rows gotten 1,000 table scan disk non-IMC rows gotten 1,000 table scan blocks gotten 1,000 buffer is pinned count 2,000 buffer is not pinned count 2,091 parse count (total) 1,035 parse count (hard) 8 execute count 1,033 bytes sent via SQL*Net to client 338,878 bytes received via SQL*Net from client 380,923 SQL*Net roundtrips to/from client 1,003 PL/SQL procedure successfully completed. --------------------------------- Library Cache - 23-Apr 17:41:06 Interval:- 4 seconds --------------------------------- Type Cache Gets Hits Ratio Pins Hits Ratio Invalid Reload ---- ----- ---- ---- ----- ---- ---- ----- ------- ------ NAMESPACE SQL AREA 1,040 1,032 1.0 1,089 1,073 1.0 0 1 NAMESPACE TABLE/PROCEDURE 17 16 .9 101 97 1.0 0 0 NAMESPACE BODY 9 9 1.0 26 26 1.0 0 0 NAMESPACE SCHEDULER GLOBAL ATTRIBU 40 40 1.0 40 40 1.0 0 0 PL/SQL procedure successfully completed.
The thing to notice, of course, is the large number of statistics that are (close to) multiples of 1,000 – i.e. the number of executions of the SQL statement. In particular you can see the ~1,000 “parse count (total)” which is not reflected in the “parse count (hard)” because the statement only needed to be loaded into the library cache and optimized once.
The other notable statistics come from the library cache where we do 1,000 gets and pins on the “SQL AREA” – the “get” creates a “KGL Lock” (the “breakable parse lock”) that is made visible as an entry in v$open_cursor (x$kgllk), and the the “pin” created a “KGL Pin” that makes it impossible for anything to flush the child cursor from memory while we’re executing it.
So what changes when we enabled the session cursor cache:
============================ Session cursor cache enabled ============================ Session altered. --------------------------------- Session stats - 23-Apr 17:41:09 Interval:- 3 seconds --------------------------------- Name Value ---- ----- Requests to/from client 1,002 opened cursors cumulative 1,004 user calls 2,005 session logical reads 9,003 non-idle wait count 1,013 db block gets 2,000 db block gets from cache 2,000 db block gets from cache (fastpath) 2,000 consistent gets 7,003 consistent gets from cache 7,003 consistent gets pin 7,000 consistent gets pin (fastpath) 7,000 logical read bytes from cache 73,752,576 calls to kcmgcs 5,002 calls to get snapshot scn: kcmgss 1,002 no work - consistent read gets 1,000 table scans (short tables) 1,000 table scan rows gotten 1,000 table scan disk non-IMC rows gotten 1,000 table scan blocks gotten 1,000 session cursor cache hits 1,000 session cursor cache count 3 buffer is pinned count 2,000 buffer is not pinned count 2,002 parse count (total) 1,002 execute count 1,003 bytes sent via SQL*Net to client 338,878 bytes received via SQL*Net from client 380,923 SQL*Net roundtrips to/from client 1,003 PL/SQL procedure successfully completed. --------------------------------- Library Cache - 23-Apr 17:41:09 Interval:- 3 seconds --------------------------------- Type Cache Gets Hits Ratio Pins Hits Ratio Invalid Reload ---- ----- ---- ---- ----- ---- ---- ----- ------- ------ NAMESPACE SQL AREA 5 5 1.0 1,014 1,014 1.0 0 0 NAMESPACE TABLE/PROCEDURE 7 7 1.0 31 31 1.0 0 0 NAMESPACE BODY 6 6 1.0 19 19 1.0 0 0 PL/SQL procedure successfully completed.
The first thing to note is that “parse count (total)” still shows up 1,000 parse calls. However we also see the statistic “session cursor cache hits” at 1,000. Allowing for a little noise around the edges virtually every parse call has turned into a short-cut that takes us through the session cursor cache directly to the correct cursor.
This difference shows up in the library cache activity where we still see 1,000 pins – we have to pin the cursor to execute it – but we no longer see 1,000 “gets”. In the absence of the session cursor cache the session has to keep searching for the statement then creating and holding a KGL Lock while we execute the statement – but when the cache is enabled the session will very rapidly recognise that the statement is one we are likely to re-use, so it will continue to hold the KGL lock
after we have finished executing the statement and we can record the location of the KGL lock in a session state object. After the first couple of executions of the statement we no longer have to search for the statement and attach a spare lock to it, we can simply navigate from our session state object to the cursor.
As before, the KGL Lock will show up in v$open_cursor – though this time it will not disappear between executions of the statement. Over the history of Oracle versions the contents of v$open_cursor have become increasingly helpful, so I’ll just show you what the view held for my session by the end of the test:
SQL> select cursor_type, sql_text from V$open_cursor where sid = 250 order by cursor_type, sql_text;
CURSOR_TYPE SQL_TEXT
---------------------------------------------------------------- ------------------------------------------------------------
DICTIONARY LOOKUP CURSOR CACHED BEGIN DBMS_OUTPUT.DISABLE; END;
DICTIONARY LOOKUP CURSOR CACHED BEGIN snap_libcache.end_snap; END;
DICTIONARY LOOKUP CURSOR CACHED BEGIN snap_my_stats.end_snap; END;
DICTIONARY LOOKUP CURSOR CACHED SELECT DECODE('A','A','1','2') FROM SYS.DUAL
OPEN begin dbms_application_info.set_module(
OPEN table_1_ff_2eb_0_0_0
OPEN-RECURSIVE SELECT VALUE$ FROM SYS.PROPS$ WHERE NAME = 'OGG_TRIGGER_OPT
OPEN-RECURSIVE select STAGING_LOG_OBJ# from sys.syncref$_table_info where t
OPEN-RECURSIVE update user$ set spare6=DECODE(to_char(:2, 'YYYY-MM-DD'), '0
PL/SQL CURSOR CACHED SELECT INDX, KGLSTTYP LTYPE, KGLSTDSC NAME, KGLSTGET GETS, K
PL/SQL CURSOR CACHED SELECT STATISTIC#, NAME, VALUE FROM V$MY_STATS WHERE VALUE !
SESSION CURSOR CACHED BEGIN DBMS_OUTPUT.ENABLE(1000000); END;
SESSION CURSOR CACHED BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
SESSION CURSOR CACHED BEGIN snap_libcache.start_snap; END;
SESSION CURSOR CACHED BEGIN snap_my_stats.start_snap; END;
SESSION CURSOR CACHED select * from t1 where n1 = 0
SESSION CURSOR CACHED select /*+ no_parallel */ spare4 from sys.optstat_hist_contr
17 rows selected.
The only one of specific interest is the penultimate one in the output – its type is “SESSION CURSOR CACHED” and we can recognise our “select from t1” statement.
I can’t find code for the snap_libcache package — could you provide that please?
Comment by dfitzjarrell — November 14, 2019 @ 5:58 pm GMT Nov 14,2019 |
David,
I’ve just posted a version of the code that should work for 11.2 onwards.
Regards
Jonathan Lewis
Comment by Jonathan Lewis — November 17, 2019 @ 9:49 am GMT Nov 17,2019 |