Oracle Scratchpad

April 23, 2019

Parse Calls

Filed under: Infrastructure,Oracle — Jonathan Lewis @ 6:31 pm BST Apr 23,2019

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.

7 Comments »

  1. 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 | Reply

  2. 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:

    SQL> select sql_id, parse_calls, executions, loads, invalidations from v$sqlstats where sql_id='3p15smkjk8b7d';
    
    SQL_ID        PARSE_CALLS EXECUTIONS      LOADS INVALIDATIONS
    ------------- ----------- ---------- ---------- -------------
    3p15smkjk8b7d     9527184    9526966        918           893
    
    

    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 CACHED
    

    The 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:

    
    SQL> select sql_id, cursor_type, count(cursor_type) from v$open_cursor where sql_id='2hqx00a8wv4wu' group by sql_id, cursor_type;
    
    SQL_ID        CURSOR_TYPE                          COUNT(CURSOR_TYPE)
    ------------- ------------------------------------ ------------------
    2hqx00a8wv4wu OPEN                                                 34
    

    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 | Reply

    • Jie,

      “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?”

      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.

      “if this particular sql is in session cursor cache, why v$sqlstats (and also in AWR reports) indicates ~0 exec to parse ratio?”

      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”.

      “does it mean that this cursor is in library cache(KGLH0 and SQLAREA) but not in session cursor cache?”

      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.

      I read from somewhere that “v$open_cursor shows cached cursors, not currently open cursors, by session”.

      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:

      Session stats for a given session
      NAME                                                   VALUE
      ------------------------------------------------- ----------
      opened cursors current                                     6
      session cursor cache count                                 4
      
      v$open_cursor for the session.
      CURSOR_TYPE                          COUNT(*)
      ---------------------------------- ----------
      OPEN-RECURSIVE                              2
      OPEN                                        4
      SESSION CURSOR CACHED                       3
      BUNDLE DICTIONARY LOOKUP CACHED             1
      
      

      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 | Reply

    • 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:

      SQL> select sql_id, cursor_type, count(cursor_type) from v$open_cursor where sql_id='2hqx00a8wv4wu' group by sql_id, cursor_type;
      
      SQL_ID        CURSOR_TYPE                                                      COUNT(CURSOR_TYPE)
      ------------- ---------------------------------------------------------------- ------------------
      2hqx00a8wv4wu OPEN                                                                             74
      
      SQL> select sql_id, parse_calls, executions, loads, invalidations from v$sqlstats where sql_id='2hqx00a8wv4wu';
      
      SQL_ID        PARSE_CALLS EXECUTIONS      LOADS INVALIDATIONS
      ------------- ----------- ---------- ---------- -------------
      2hqx00a8wv4wu         189     109147        183           153
      

      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 | Reply

      • Jie,

        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.

        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 | Reply

  3. Thank you, Jonathan!

    Comment by Anonymous — January 18, 2020 @ 4:19 am GMT Jan 18,2020 | Reply


RSS feed for comments on this post. TrackBack URI

Comments and related questions are welcome.

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

This site uses Akismet to reduce spam. Learn how your comment data is processed.

Powered by WordPress.com.