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 (global) 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 activity 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” creates a “KGL Pin” that makes it impossible for anything to flush the child cursor from memory while we’re using 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 child cursor.
This difference is echoed 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 that we are likely to re-use, so it will continue to hold the KGL lock (releasing the KGL pin, of course) 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 |
Hi Sir,
I hope you can explain this conflicting finding for me. I have this sql that has execution to parse ratio close to 0 according to v$sqlstats:
v$open_cursor suggests this sql is in session cursor cache:
SQL> select sid, sql_id, cursor_type from v$open_cursor where sql_id='3p15smkjk8b7d'; SID SQL_ID CURSOR_TYPE ---------- ------------- ------------------------------------ 1170 3p15smkjk8b7d SESSION CURSOR CACHED 1643 3p15smkjk8b7d SESSION CURSOR CACHED 2554 3p15smkjk8b7d SESSION CURSOR CACHED 4495 3p15smkjk8b7d SESSION CURSOR CACHED 4505 3p15smkjk8b7d SESSION CURSOR CACHED 843 3p15smkjk8b7d SESSION CURSOR CACHED 3352 3p15smkjk8b7d SESSION CURSOR CACHED 1630 3p15smkjk8b7d SESSION CURSOR CACHED 4386 3p15smkjk8b7d SESSION CURSOR CACHED 2446 3p15smkjk8b7d SESSION CURSOR CACHED 4169 3p15smkjk8b7d SESSION CURSOR CACHED 1878 3p15smkjk8b7d SESSION CURSOR CACHED 1857 3p15smkjk8b7d SESSION CURSOR CACHED 1384 3p15smkjk8b7d SESSION CURSOR CACHED 4287 3p15smkjk8b7d SESSION CURSOR CACHED 1285 3p15smkjk8b7d SESSION CURSOR CACHED 935 3p15smkjk8b7d SESSION CURSOR CACHED 2651 3p15smkjk8b7d SESSION CURSOR CACHEDThe client is a JDBC program. My understanding has been that if a sql is found in session cache cursor, it will go through a “softer” soft parse and the “parse_calls” would not be incremented. is my understanding wrong? and if this particular sql is in session cursor cache, why v$sqlstats (and also in AWR reports) indicates ~0 exec to parse ratio?
what does it exactly meant when the cursor_type is “OPEN”? from this output:
does it mean that this cursor is in library cache(KGLH0 and SQLAREA) but not in session cursor cache?
I read from somewhere that “v$open_cursor shows cached cursors, not currently open cursors, by session”. And I search on internet and could not find a define answer. It would be great if you can write up an article and explain in detail all these and clear the misinformation on the internet.
Thanks,
Jie
Comment by Jie Wu — January 13, 2020 @ 12:10 am GMT Jan 13,2020 |
Jie,
I wrote this article to demonstrate that you will still record a “parse call” even when a cursor is recorded in the session’s cursor cache, so clearly the second half of your understanding was wrong. The same message appears in the two articles I linked to at the start of the post.
As a crude general guideline – don’t think about ratios, they don’t help. I’ll also point out that you haven’t defined what you mean by the “exec to parse” ratio – when I look at the results from your query I’d say your “exec to parse” ratio was 100% – every execution required a parse call. (I am aware, by the way, that the AWR/Statspack report uses the word “ratio” but arbitrarily throws in a “1 – ” component into the arithmetic to make 0 the “bad” value and 100 the “good” value.)
If your client code uses a style that says: “here’s a piece of SQL, execute it”, then it will almost certain be doing a parse call and the session will record a “parse call” as well as an “execute” call. If your client code is written knowing that it will re-execute the same text many times, it will issue an explicit “parse this statement and give me a handle”, followed by many calls to “execute the statement identified by this handle” and record one “parse call” and many “execute”.
Probably – but I haven’t investigated this detail – the view and its contents have changed quite significantly over recent versions. Very specifically it means that there is a KGL lock (x$kgllk) connecting the child cursor with the session. Whether the cursor is “really” open or not I don’t know.
When saying “I read somewhere … “ it’s good to cite the source if you can remember (or rediscover) it, as the intention of the author may be clearer once the context is available. I found this phrase at: https://www.orafaq.com/node/758 (which includes the phrase “Tom Kyte recommends setting it around 1000” without a citation, and I’d really like to see the context of that comment because I would be a little surprisied if he intended it to be a general guideline).
I think the context of the comment means that its intention is:
“v$open_cursor will show you cursors that are cached as well as cursors that are open.” The original phrase could do with being edited to read “not JUST currently open cursors”. It’s also worthing noting that the article is dated 2005, so there’s plenty of time for details to change.
In passing, doing a VERY quick check on v$open_cursor on a 19.3 I get the following type of results by comparing v$open_cursors and v$sesstat:
Opened cursors current seems to include user open and recursive open, while session cursor cache count seems to include user cached and dictionary cache.
Regards
Jonathan Lewis
Comment by Jonathan Lewis — January 13, 2020 @ 2:47 pm GMT Jan 13,2020 |
Hi Jonathan,
Thanks for taking time to answer my question. The parsing/execution is clear to me now. it looks like the JDBC client is not using a handle to re-execute the same sql statement (sql_id 3p15smkjk8b7d). Since on the db side it is cached in the session cursor cache, only “gets” would take place and there is some overhead related to all the “gets” but the overhead of “pins” is gotten rid of. What about the overhead caused by not re-using a handle? is there any?
For the other sql_id, I see:
So looks like the client code is re-using a handle, but the “OPEN” cursor type instead of “SESSION CURSOR CACHED” may suggest it is not in session cursor cache. is there any other way that you know of that can confirm whether it is in session cache cursor? Our session_cached_cursor is set to 1600 so I am expecting that this sql should be in session cursor cache as well. if it turns out not the case, I will need to reach out the app team to investigate if statement caching is enabled in the client code.
If you can find time to clarify what “OPEN” means and blog about it, i am sure it will be appreciated by many folks:)
Thanks!
Comment by Anonymous — January 13, 2020 @ 5:01 pm GMT Jan 13,2020 |
Jie,
Right sort of idea, but the wrong way round. You have to have a “pin” while the cursor is executing so that the child cursor doesn’t get flushed from memory – that “overhead” is always there. If a session has recorded a child cursor in the session cursor cache then it doesn’t have to do the “get”.
Your sample statement is doing better than being in the session cursor cache. It’s an example of a HELD cursor so from the database perspective the client is sending it a message saying “go and execute the thing you find at this location”; it’s NOT saying “search the SQL area for this statement and see if you can execute it”, or “search your session cursor cache to see if you’re caching this statement and follow the link to execute it if you are”.
It’s possible that your client code has been explicitly written to open the cursor and hold the handle; however it’s possible that your client code has a driver between it and the database which doesn’t send the “close cursor” message to the database but has its own statement cache that holds the cursor open in case you want (from the client code perspective) to re-open it again later on. Typically you set this cache size in the client code when you create the connection and there’s some LRU mechanism that eventually sends a real “close cursor” call to Oracle when your code wants to cache yet another statement and the cache is full. Here’s a link to the Oracle JDBC manual that might give you (or your developers) a better idea of what can be done – it’s not my speciality.
Regards
Jonathan Lewis
Comment by Jonathan Lewis — January 14, 2020 @ 5:06 pm GMT Jan 14,2020 |
Thank you, Jonathan!
Comment by Anonymous — January 18, 2020 @ 4:19 am GMT Jan 18,2020 |