Tables and Their Indexes Should be Located on Different Disks – What is Wrong with this Quote?

17 02 2012

February 17, 2012

As I mentioned in a previous blog article, I placed an order for the book “Oracle Database 11gR2 Performance Tuning Cookbook“, mostly because I was curious how the book would compare with the “Oracle Database 11g Performance Tuning Recipes” book (my review of that book was a total of about 35 typewritten pages in length), and some of the other Oracle performance related books that I have reviewed.

After placing my order for the book, I took a quick look at a couple of the book’s preview pages on Amazon, downloaded the sample chapter from the book publisher – chapter 10 “Tuning I/O”, and spent a bit of time reading the sample chapter (making comments in the margins of the printed pages).  I circled the following paragraph (sorry for the long quote – I want to make certain that the context of the quote is not lost), found on page 422 of the book (page 17 in the PDF download):

“We can also distribute tables and related indexes on different disks, to obtain performance gain in both read and write operations. If we have tables and indexes on the same disk, we need to read and write in two different places on the same disk. By dividing the work between two disks, we can perform an index range scan faster than when the index and the table are on the same disk.”

What, if anything, is wrong with the above quote from the book?  For some reason, the acronym MASE came to mind when I read the above paragraph. 

The point of blog articles like this one is not to insult authors who have spent thousands of hours carefully constructing an accurate and helpful book, but instead to suggest that readers investigate when something stated does not exactly match what one believes to be true.  It could be that the author “took a long walk down a short pier”, or that the author is revealing accurate information which simply cannot be found through other resources (and may in the process be directly contradicting information sources you have used in the past).  If you do not investigate in such cases, you may lose an important opportunity to learn something that could prove to be extremely valuable.





SESSIONS Derived Value Formula – Doc Bug Explains

8 02 2012

February 8, 2012

Default parameter values are great, as long as it is possible to predict the default values, and the defaults are appropriate for the environment in which the defaults are present.  It is sometimes a challenge to remember all of the rules, and exceptions to those rules, that determine the defaults. I had a vague recollection of how the value of the SESSIONS parameter value is derived from the value of the PROCESSES parameter value.  An Oracle Database 11.2.0.2 question recently arrived in my email box from an ERP mailing list.  The original poster (OP) showed the following output in the email:

SQL> show parameter sessions

NAME                                 TYPE        VALUE
------------------------------------ ----------- -----
sessions                             integer     624

SQL> show parameter processes

NAME                                 TYPE        VALUE
------------------------------------ ----------- -----
processes                            integer     400 

At first glance, I thought that the OP made a mistake with the manual specification of the SESSIONS parameter value when taking into consideration the current value of the PROCESSES parameter value.

A Google search found a couple of helpful discussion threads that seemed to provide a formula that showed how the default value for the SESSIONS parameter is derived.  I decided to also perform a Google search of the Oracle documentation (trying to avoid circular references).   The same formula found in the helpful discussion threads is also included in the documentation, so that lends a bit of credibility to the information.  Let’s take a look at the Oracle Database 11.2 documentation for the SESSIONS parameter:

Default Value: Derived: (1.1 * PROCESSES) + 5

“… You should always set this parameter explicitly to a value equivalent to your estimate of the maximum number of concurrent users, plus the number of background processes, plus approximately 10% for recursive sessions.

Oracle uses the default value of this parameter as its minimum. Values between 1 and the default do not trigger errors, but Oracle ignores them and uses the default instead.”

A second page from the documentation library included additional information about the PROCESSES parameter:

“Oracle uses the default value of this parameter as its minimum. Values between 1 and the default do not trigger errors, but Oracle ignores them and uses the default instead…”

If you plan on running 50 user processes, a good estimate would be to set the PROCESSES initialization parameter to 70.”

So, let’s take another look at the PROCESSES value specified by the OP, keeping in mind the information from the documentation.  The OP has a database instance with a PROCESSES value of 400, and with the insight provided by the first documentation quote, that would suggest that the SESSIONS parameter would have been autoset to a value of (1.1 * 400) + 5 = 445.  That formula result coupled with the first paragraph of the second quote might lead someone to believe that the OP manually set the SESSIONS value to 624 – there could be a good reason for doing so.  The second paragraph in the second quote from the documentation suggests that OP’s PROCESSES value would allow about (400 – (70 – 50)) =  380 user processes  (each session will require 1 dedicated process, so that value would permit about 380 user sessions).

In an earlier blog article we saw that the auto-tuned value of the DB_FILE_MULTIBLOCK_READ_COUNT parameter is dependent, in part, on the value of the SESSIONS parameter and the size of the SGA.  In another blog article we found that the maximum number of blocks read by serial direct path read is the greatest power of 2 that is equal to or less than the value of the DB_FILE_MULTIBLOCK_READ_COUNT parameter.  Various other items are also affected by the SESSIONS parameter value, so setting the value to too high of a value has few rewards.

So, did the OP make a mistake when setting the SESSIONS parameter value?  I took a look at a test 11.2.0.2 database instance where I had set the PROCESSES parameter to a value of 150 and left the SESSIONS parameter unset.  The SESSIONS parameter value in the 11.2.0.2 database instance showed a value of 248 when I opened the database and executed:

SHOW PARAMETER SESSIONS

Something a bit stange is happening.  Oracle Database 10.2 seemed to respect the 11.2 documentation’s formula for the auto-calculation of the SESSIONS parameter, but Oracle Database 11.2.0.2 seems to use a different formula.  It was late at night when I posted my reply, so I guessed that the formula was about (1.52 * PROCESSES) + 20 (it was too late at night for thinking in terms of basic algebra, so I just picked a set of numbers that worked with my test PROCESSES and SESSIONS parameter values).

Since responding to the email, I took a sampling of a couple of 11.2.0.2 database instances, and summarized those findings below, including the actual derived SESSIONS value and the calculated value using the formula from the documentation:

PROCESSES SESSIONS
(Actual Derived)
SESSIONS
(Documentation Derived)
330 520 368
150 248 170
400 624 445
60 112 71
80 144 93

The actual numbers don’t quite match what the documentation suggests.

Time for a little basic algebra.  The formula from the documentation could be represented as:

(x * PROCESSES) + y = SESSIONS

If the structure of the above formula is still correct, just with unknown values for x and y, we will need at least two sets of equations to determine the value of the x and y variables.  To find the x and y variable values, we will use the known PROCESSES and actual derived SESSIONS values from first two rows of the above table:

(x * 330) + y = 520
(x * 150) + y = 248

Solving for y in the first equation:

y = 520 - (x * 330)
y = 520 - 330x

Substituting the above value of y into the second equation to solve for x:

(x * 150) + (520 - 330x) = 248
150x + 520 - 330x = 248
-180x = -272
x = 272/180
x = 1.51111111

Plug the value for x into the above equation for y:

y = 520 - 330x
y = 520 - 330*(1.51111111)
y = 21.3333337

So, based on the values from the first two rows from the above table, in Oracle Database 11.2.0.2:

SESSIONS = (1.51111111 * PROCESSES) + 21.3333337

The above formula works for the first, second, and fourth rows in the above table, but the formula is a bit off for the remaining two rows:

PROCESSES SESSIONS
(Actual Derived)
SESSIONS
(Documentation Derived)
   Formula 1
330 520 368   520
150 248 170   248
400 624 445   625.77778
60 112 71   112
80 144 93   142.22222

Let’s try solving the formula again using the values from the two rows that did not agree with the new formula for the derived SESSIONS parameter value:

(x * 400) + y = 624
(x * 80) + y = 144

Solving for y in the first equation:

y = 624 - (x * 400)
y = 624 - 400x

Substituting the above value of y into the second equation to solve for x:

(x * 80) + (624 - 400x) = 144
80x - 400x + 624 = 144
-320x = -480
x = 480/320
x = 1.5

Plug the value for x into the above equation for y:

y = 624 - 400 * 1.5
y = 624 - 600
y = 24

The above result leads to the following formula:

SESSIONS = (1.5 * PROCESSES) + 24

Let’s take a look at the values generated by the two formulas side-by-side with the actual derived SESSIONS values:

PROCESSES SESSIONS
(Actual Derived)
SESSIONS
(Documentation Derived)
  Formula 1 Formula 2
330 520 368   520 519
150 248 170   248 249
400 624 445   625.77778 624
60 112 71   112 114
80 144 93   142.22222 144

Interesting results… Doc Bug?  Why three formulas (plus the guess that I wrote in the email)?  No wonder it is sometimes difficult to remember the default derived values for parameters.

What about this suggestion from the documentation:

“If you plan on running 50 user processes, a good estimate would be to set the PROCESSES initialization parameter to 70.”

That suggestion might also be out of date.  From a generic test 11.2.0.2 Standard Edition database instance running on Windows:

SELECT
  COUNT(*)
FROM
  V$SESSION
WHERE
  USERNAME IS NULL;

COUNT(*)
--------
      27

SELECT
  PROGRAM
FROM
  V$SESSION
WHERE
  USERNAME IS NULL
ORDER BY
  PROGRAM;

PROGRAM
-----------------
ORACLE.EXE (ARC0)
ORACLE.EXE (ARC1)
ORACLE.EXE (ARC2)
ORACLE.EXE (ARC3)
ORACLE.EXE (CJQ0)
ORACLE.EXE (CKPT)
ORACLE.EXE (DBRM)
ORACLE.EXE (DBW0)
ORACLE.EXE (DIA0)
ORACLE.EXE (DIAG)
ORACLE.EXE (GEN0)
ORACLE.EXE (J000)
ORACLE.EXE (J001)
ORACLE.EXE (LGWR)
ORACLE.EXE (MMAN)
ORACLE.EXE (MMNL)
ORACLE.EXE (MMON)
ORACLE.EXE (PMON)
ORACLE.EXE (PSP0)
ORACLE.EXE (Q001)
ORACLE.EXE (Q002)
ORACLE.EXE (QMNC)
ORACLE.EXE (RECO)
ORACLE.EXE (SMCO)
ORACLE.EXE (SMON)
ORACLE.EXE (VKTM)
ORACLE.EXE (W000) 

Interesting results… Doc Bug?  So this generic Standard Edition database has 27 background processes.  Maybe this page in the documentation needs a little work also?  Ah, Doc Bug explains it.





The Transforming Face of the Oracle Support Site

23 12 2011

December 23, 2011

A day or two ago I saw an announcement that the HTML (non-Flash) version of the Oracle Support site was to be phased out in January 2012.  It seems like the last time I tried to use that site, the search functionality did not quite work for Oracle Database products; I gave up on the HTML version of the site and went back to the Flash-based version of the site. 

The performance of the Flash-based version of Metalink (I usually navigate to the site by entering metalink.oracle.com into the web browser’s address bar) My Oracle Support has improved significantly since the initial launch, and it appears that once the website is loaded, it is a bit more stable now.  I do not own any i products (iPhone, iPad, iToy) which do not support Flash, so the Flash-based version of the Oracle support site works OK on most of my devices (Windows 7 64 bit with IE 9, Windows 7 32 bit with IE 8, Windows XP 32 bit, Motorola Xoom, Amazon BlackBerry Playbook, etc.) as long as Flash is supported in the web browser.  Now the shocker, the Flash-based version of the support site is also planned to be phased out, based on Metalink (MOS) Doc ID 1385682.1.

Turning the other cheek, or doing an about-face?  The support document mentions that ADF Faces will be used – the site will be built using Oracle Application Development Framework.  I hate to say that this is a case of Oracle eating its own dog food – maybe there is a better way to state that the support site will be using their own technology rather than the technology of a third party?  I wonder if the Oracle OTN forums are also being redesigned to use Oracle technology, rather than that of a third party?  On a related note, it appears that the OTN forum site has fixed the Internal Server Error problem.

Anyone found any additional information about the change to the support site?  Any experience with ADF Faces?





What Could Go Wrong? Testing the DB_FILE_MULTIBLOCK_READ_COUNT Parameter

14 10 2011

October 14, 2011 (Modified October 15, 2011)

When reading various Oracle Database books, I often perform mental exercises related to the book’s contents, asking “what could go wrong?”   That is probably why some of my book reviews have extended to record setting lengths… who knew that Amazon imposed a limit on book review lengths…

I recently started re-reading the “Troubleshooting Oracle Performance” book after buying a PDF copy of the book.  As previously mentioned, the ultimate reason for re-reading the book is so that I may compose a detailed book review, just as I have done for most of the Oracle Database related books that I have read in the past couple of years.  So far, I have had few opportunities to ask “what could go wrong” – until of course I made it to page 178 during the second read-through of the book.  That page includes a PL/SQL block that tests the performance effects of modifying the DB_FILE_MULTIBLOCK_READ_COUNT parameter from a value of 1 to 32, increasing the value by 1 for each pass through the loop in the PL/SQL block.  What could go wrong?

Let’s build a sample table with 11,000,000 rows:

DROP TABLE T1 PURGE;

CREATE TABLE T1(
  C1 NUMBER,
  C2 NUMBER,
  C3 NUMBER,
  C4 DATE,
  C5 DATE,
  C6 DATE,
  C7 VARCHAR2(20),
  C8 VARCHAR2(20),
  C9 VARCHAR2(20));

INSERT INTO
  T1
SELECT
  ROWNUM,
  DECODE(MOD(ROWNUM,5),0,NULL,ROWNUM),
  DECODE(MOD(ROWNUM,5),0,NULL,ROWNUM),
  TRUNC(SYSDATE)+TRUNC(ROWNUM/100),
  DECODE(MOD(ROWNUM,5),0,NULL,TRUNC(SYSDATE)+TRUNC(ROWNUM/100)),
  DECODE(MOD(ROWNUM,5),0,NULL,TRUNC(SYSDATE)+TRUNC(ROWNUM/100)),
  RPAD(CHR(MOD(ROWNUM-1,26)+65)||
    CHR(MOD(ROWNUM,26)+65)||
    CHR(MOD(ROWNUM+1,26)+65)||
    CHR(MOD(ROWNUM+2,26)+65),20,'A'),
  DECODE(MOD(ROWNUM,5),0,NULL,
   RPAD(CHR(MOD(ROWNUM-1,26)+65)||
    CHR(MOD(ROWNUM,26)+65)||
    CHR(MOD(ROWNUM+1,26)+65)||
    CHR(MOD(ROWNUM+2,26)+65),20,'A')),
  DECODE(MOD(ROWNUM,5),0,NULL,
   RPAD(CHR(MOD(ROWNUM-1,26)+65)||
    CHR(MOD(ROWNUM,26)+65)||
    CHR(MOD(ROWNUM+1,26)+65)||
    CHR(MOD(ROWNUM+2,26)+65),20,'A'))
FROM
  DUAL
CONNECT BY
  LEVEL<=1000000;

INSERT INTO
  T1
SELECT
  T1.*
FROM
  T1,
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=10);

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',ESTIMATE_PERCENT=>NULL)

The above script might take a minute or two to complete.  Let’s take a look at the extent sizes for table T1:

SELECT
  SEGMENT_NAME SEGMENT,
  COUNT(*) EXTENTS,
  BYTES/1024 EXT_SIZE_KB,
  (COUNT(*) * BYTES)/1048576 TOTAL_MB
FROM
  DBA_EXTENTS
WHERE
  OWNER=USER
  AND SEGMENT_NAME IN ('T1')
GROUP BY
  SEGMENT_NAME,
  BYTES
ORDER BY
  SEGMENT_NAME,
  BYTES;

SEGMENT    EXTENTS EXT_SIZE_KB   TOTAL_MB
------- ---------- ----------- ----------
T1              16          64          1
T1              63        1024         63
T1             120        8192        960
T1               2       65536        128

Now let’s try a slightly modified version of the script that appears in the book:

SET SERVEROUTPUT ON
SET TIMING ON

DECLARE
  L_COUNT PLS_INTEGER;
  L_TIME PLS_INTEGER;
  L_STARTING_TIME PLS_INTEGER;
  L_ENDING_TIME PLS_INTEGER;
BEGIN
  DBMS_OUTPUT.PUT_LINE('DBFMBRC SECONDS');
  FOR L_DBFMBRC IN 1..128
  LOOP
    EXECUTE IMMEDIATE 'ALTER SESSION SET DB_FILE_MULTIBLOCK_READ_COUNT='||L_DBFMBRC;
    L_STARTING_TIME := DBMS_UTILITY.GET_TIME();
    SELECT /*+ FULL(T) */ COUNT(*) INTO L_COUNT FROM T1 T;
    L_ENDING_TIME := DBMS_UTILITY.GET_TIME();
    L_TIME := ROUND((L_ENDING_TIME-L_STARTING_TIME)/100);
    DBMS_OUTPUT.PUT_LINE(L_DBFMBRC||' '||L_TIME);
  END LOOP;
END;
/

-

-

-

-

-

-

-

-

-

-

-

-

-

The output that I received when tested on Oracle Database 11.2.0.2 follows:

DBFMBRC SECONDS
1 0
2 0
3 0
4 0
5 0
6 0
7 0
8 0
9 0
10 0
11 0
12 0
13 0
14 0
15 0
16 0
17 0
18 0
19 0
20 0
21 0
22 0
23 0
24 0
25 0
26 0
27 0
28 0
29 0
30 0
31 0
32 0
33 0
34 0
35 0
36 0
37 0
38 0
39 0
40 0
41 0
42 0
43 0
44 0
45 0
46 0
47 0
48 0
49 0
50 0
51 0
52 0
53 0
54 0
55 0
56 0
57 0
58 0
59 0
60 0
61 0
62 0
63 0
64 0
65 0
66 0
67 0
68 0
69 0
70 0
71 0
72 0
73 0
74 0
75 0
76 0
77 0
78 0
79 0
80 0
81 0
82 0
83 0
84 0
85 0
86 0
87 0
88 0
89 0
90 0
91 0
92 0
93 0
94 0
95 0
96 0
97 0
98 0
99 0
100 0
101 0
102 0
103 0
104 0
105 0
106 0
107 0
108 0
109 0
110 0
111 0
112 0
113 0
114 0
115 0
116 0
117 0
118 0
119 0
120 0
121 0
122 0
123 0
124 0
125 0
126 0
127 0
128 0

PL/SQL procedure successfully completed.

What Could Go Wrong?  (I had two or three answers for this question as I was reading the script, but I have a couple more after a bit of experimentation.  Think about what might go wrong without looking in the book.)

Added October 15, 2011:

The “Troubleshooting Oracle Performance” book, to my knowledge, was the first performance tuning book to address Oracle Database 11.1, and this book was released shortly after the release of Oracle Database 11.1.0.6.  While it was not widely known at the time (I do not think that it was documented), Oracle Database 11.1.0.6 might employ serial direct path reads (directly into the PGA) rather than db file scattered reads (into the buffer cache) when performing a full table scan.  Based on an experiment, the DB_FILE_MULTIBLOCK_READ_COUNT parameter influences the maximum number of blocks read in a single direct path read request; the maximum number of blocks read by direct path read appears to be the greatest power of two that is equal to or less than the value of the the DB_FILE_MULTIBLOCK_READ_COUNT parameter.  The paragraphs that follow this test case in the book suggest that a parallel full table scan should not be utilized – that implies that the book author is aware that direct path reads might distort the outcome of the test case.  This was the first thought that I had when viewing this test case when re-reading the book.

The effects of the table blocks that are already buffered in the buffer cache is also a potential area where this test case might see distorted results (the paragraphs that follow this test case in the book address this issue).  The test table is roughly 1,152MB in size (minus the blocks that are above the high water mark, of course), so how likely is it that some of the table blocks might be cached in the buffer cache either before the first execution of the SELECT from the table T1, or between executions of the SELECT from T1?  Does the answer depend on what was performed prior to the test case – how full is the buffer cache with unrelated blocks?  What is possibly interesting is that in my test case, all of the blocks belonging to the entire table were buffered in the buffer cache prior to the start of the PL/SQL block in the test case.  Without the timing information displayed by SET TIMING ON, it is difficult to determine if the DBMS_UTILITY.GET_TIME function simply is not supported on the operating system platform used for the test, or if as Timur stated in the comments section, the full table scans were completing so quickly that the timing of the individual runs was being rounded to 0 seconds.  I was careful not to include the output of the SQL*Plus timing during the initial posting of the blog article.  I obtained the following times from repeated PL/SQL executions:

Elapsed: 00:00:39.37

Elapsed: 00:00:37.05

Elapsed: 00:00:37.14

With a 10046 trace enabled, the execution time climbed sharply:

...
125 1
126 1
127 1
128 1

PL/SQL procedure successfully completed.

Elapsed: 00:01:40.16

The potential buffering of some or all of the table blocks was the second thought that I had while reading the test case during the re-read of the book.  The paragraph in the book that followed the test case addressed the potential problems of the table blocks being cached in the buffer cache, the operating system cache, a SAN cache, or a similar cache.  As previously mentioned, Oracle Database 11.1.0.6 and later are able to perform serial direct path reads, where previous Oracle Database versions would have used db file scattered reads, so the Oracle Database version is potentially important.  The book previously mentioned on page 175 three items that might cause fewer blocks to be read than what is specified by the DB_FILE_MULTIBLOCK_READ_COUNT parameter – those items might impact the results of the test, if the test table is not representative of the other objects in the database that might be read by a db file scattered read.

While reading the test case, another thought raced through my mind: why is the author experimenting with the DB_FILE_MULTIBLOCK_READ_COUNT parameter – just leave it unset and make certain that system statistics are collected so that the MBRC system statistic is used (I believe that this is related to Mohamed’s second point in the comments section).  Since the release of Oracle Database 10.2.0.1 it is possible to leave that parameter unset (and a bug was fixed in 10.2.0.4 that then allowed the parameter to be set to 0 which then had the same effect as leaving it unset).  That is the point that Mohamed made in the comments section.  The book author covered the possibility of leaving the DB_FILE_MULTIBLOCK_READ_COUNT parameter unset in the paragraphs that followed the test case, and since this book attempts to help with performance problems in Oracle 9.0.1 and later, it probably is a good idea that the test case was included to benefit those who had not yet transitioned all of the databases to Oracle Database 10.2 or later.

Result caching, mentioned by Steve Catmull in the comments section, is not something that I had considered while reading the test case.  If I remember correctly, when the RESULT_CACHE_MODE parameter is set to FORCE, the result cache could distort the results of the test case.

I thought that I would include a couple of more test cases on 11.2.0.2.
With an unset DB_FILE_MULTIBLOCK_READ_COUNT and the following script:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

A variety of “direct path read” wait events appear in the resulting trace file.  Two typical wait events found in the trace file follow:

WAIT #362523544: nam='direct path read' ela= 2280 file number=4 first dba=3951616 block cnt=128 obj#=71407 tim=366050651386
WAIT #362523544: nam='direct path read' ela= 2323 file number=4 first dba=3951744 block cnt=128 obj#=71407 tim=366050654201

The above shows the types of wait events that I expected to have when I read the PL/SQL block.

Let’s try again with a specified value for DB_FILE_MULTIBLOCK_READ_COUNT:

ALTER SESSION SET DB_FILE_MULTIBLOCK_READ_COUNT=20;

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

A variety of “direct path read” wait events appear in the resulting trace file.  Two typical wait events found in the trace file follow:

WAIT #362523544: nam='direct path read' ela= 272 file number=4 first dba=4061184 block cnt=16 obj#=71407 tim=366357357469
WAIT #362523544: nam='direct path read' ela= 372 file number=4 first dba=4061216 block cnt=16 obj#=71407 tim=366357357889

In the above, note that the direct path read wait did not entirely adhere to the value for the modified DB_FILE_MULTIBLOCK_READ_COUNT, the actual number of blocks was rounded down to the next lower power of 2.

Let’s try again with another value for the DB_FILE_MULTIBLOCK_READ_COUNT parameter:

ALTER SESSION SET DB_FILE_MULTIBLOCK_READ_COUNT=100;

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

A variety of “direct path read” wait events appear in the resulting trace file.  Two typical wait events found in the trace file follow:

WAIT #362523544: nam='direct path read' ela= 1206 file number=4 first dba=4050624 block cnt=64 obj#=71407 tim=366563051144
WAIT #362523544: nam='direct path read' ela= 1144 file number=4 first dba=4050688 block cnt=64 obj#=71407 tim=366563052537

In the above, note that the direct path read wait did not entirely adhere to the value for the modified DB_FILE_MULTIBLOCK_READ_COUNT, the actual number of blocks was rounded down to the next lower power of 2.

Let’s try again with another value for the DB_FILE_MULTIBLOCK_READ_COUNT parameter:

ALTER SESSION SET DB_FILE_MULTIBLOCK_READ_COUNT=120;

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

A variety of “direct path read” wait events appear in the resulting trace file.  Two typical wait events found in the trace file follow:

WAIT #362523544: nam='direct path read' ela= 1183 file number=4 first dba=4047232 block cnt=64 obj#=71407 tim=366628708554
WAIT #362523544: nam='direct path read' ela= 1280 file number=4 first dba=4047296 block cnt=64 obj#=71407 tim=366628710113

Just for verification:

ALTER SESSION SET DB_FILE_MULTIBLOCK_READ_COUNT=128;

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

Wait events:

WAIT #362523544: nam='direct path read' ela= 2505 file number=4 first dba=4050560 block cnt=128 obj#=71407 tim=366681412987
WAIT #362523544: nam='direct path read' ela= 2259 file number=4 first dba=4050688 block cnt=128 obj#=71407 tim=366681415722

The above again shows that the number of blocks read by direct path read are rounded down to the nearest power of two.

OK, let’s try the initial test again:

DISCONNECT ALL;
CONNECT ...

Instead of using a PL/SQL block, let’s use regular SQL statements:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',ESTIMATE_PERCENT=>100)

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE

SELECT /*+ FULL(T1) */ COUNT(*) FROM T1;

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE

The results, “direct path read” wait events for both of the selects from table T1:

...
WAIT #357271008: nam='direct path read' ela= 2774 file number=4 first dba=3930496 block cnt=128 obj#=71407 tim=371288846837
WAIT #357271008: nam='direct path read' ela= 2353 file number=4 first dba=3930624 block cnt=128 obj#=71407 tim=371288849736
...
WAIT #357239640: nam='direct path read' ela= 2749 file number=4 first dba=3935360 block cnt=128 obj#=71407 tim=371292356287
WAIT #357239640: nam='direct path read' ela= 2580 file number=4 first dba=3935488 block cnt=128 obj#=71407 tim=371292359340
...

Other testing showed that if the buffer cache was flushed after creating and populating the table, but before collecting statistics, Oracle Database 11.2.0.2 performed serial direct path reads to read the table blocks, rather than reading those blocks into the buffer cache using db file scattered reads.





Having Fun with ORA-00600 (qkebCreateConstantOpn1) – What is the Cause of this Error?

28 09 2011

September 28, 2011

A friend brought an interesting Oracle Database 11.2.0.2 problem to my attention. He is in the process of upgrading to a new Oracle Database server (and Oracle Database version) and a new version of an ERP package. He has experienced an ORA-00600 error with both patch 6 and patch 9 for 11.2.0.2 on 64 bit Windows after rolling forward the database table definitions for the new version of the ERP package and then testing the ERP functionality (all in a test environment, of course).

I have not seen the most recent table modification scripts first hand, but upgrade scripts for the earlier ERP versions exercised good habits of declaring column constraints and default column values (as well as triggers to make certain that SQL script writers do not get too carried away).

So, what to do to troubleshoot this problem, call Oracle support because an ORA-00600 error is returned, or poke around a little to see if we can determine what is happening? Since I am not able to touch the database to investigate the problem freely, I asked for a 10046 trace at level 12 to be generated. Below is a portion of that trace file (the portion in bold was actually executed by the client application, while the rest is at dep=1, in this case internal SQL used for query optimization):

PARSING IN CURSOR #386947304 len=42 dep=1 uid=0 oct=3 lid=0 tim=63747639340 hv=844002283 ad='314cbd908' sqlid='ftj9uawt4wwzb'
select condition from cdef$ where rowid=:1
END OF STMT
PARSE #386947304:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63747639340
BINDS #386947304:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1c28c668  bln=16  avl=16  flg=05
  value=0000A680.003D.0001
EXEC #386947304:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63747639412
FETCH #386947304:c=0,e=8,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=1884964958,tim=63747639432
STAT #386947304 id=1 cnt=1 pid=0 pos=1 obj=31 op='TABLE ACCESS BY USER ROWID CDEF$ (cr=1 pr=0 pw=0 time=4 us cost=1 size=15 card=1)'
CLOSE #386947304:c=0,e=21,dep=1,type=0,tim=63747639466
...
...
...
PARSING IN CURSOR #386943464 len=58 dep=0 uid=36 oct=6 lid=36 tim=63750497441 hv=1532843717 ad='3144ac3d8' sqlid='9m0sbg1dpupq5' 
update PART set mrp_required = :1     where id = :2       
END OF STMT 
PARSE #386943464:c=0,e=121,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=63750497440 
PARSE #386947304:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63750497602
BINDS #386947304:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1edffbd8  bln=16  avl=16  flg=05
  value=0000A7B3.0019.0001
EXEC #386947304:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63750497664
FETCH #386947304:c=0,e=9,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=1884964958,tim=63750497684
CLOSE #386947304:c=0,e=8,dep=1,type=3,tim=63750497704
=====================
PARSING IN CURSOR #517995552 len=98 dep=1 uid=0 oct=3 lid=0 tim=63750497798 hv=3044436590 ad='2f0e99070' sqlid='dha5nv6urcumf'
select binaryDefVal,           lengthb(binaryDefVal) from ecol$ where tabobj# = :1 and colnum = :2
END OF STMT
PARSE #517995552:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3081038021,tim=63750497797
BINDS #517995552:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=0001 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=1edfe758  bln=22  avl=04  flg=05
  value=18450
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=0001 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=1edfe770  bln=22  avl=03  flg=01
  value=141
EXEC #517995552:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3081038021,tim=63750497891
FETCH #517995552:c=0,e=14,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3081038021,tim=63750497913
STAT #517995552 id=1 cnt=1 pid=0 pos=1 obj=123 op='TABLE ACCESS BY INDEX ROWID ECOL$ (cr=2 pr=0 pw=0 time=11 us cost=2 size=95 card=1)'
STAT #517995552 id=2 cnt=1 pid=1 pos=1 obj=126 op='INDEX RANGE SCAN ECOL_IX1 (cr=1 pr=0 pw=0 time=8 us cost=1 size=0 card=1)'
CLOSE #517995552:c=0,e=1,dep=1,type=3,tim=63750497955
PARSE #386947304:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63750498060
BINDS #386947304:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1edfe360  bln=16  avl=16  flg=05
  value=0000A7B3.0019.0001
EXEC #386947304:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1884964958,tim=63750498120
FETCH #386947304:c=0,e=9,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=1884964958,tim=63750498140
CLOSE #386947304:c=0,e=7,dep=1,type=3,tim=63750498159
Symbol file c:\Oracle\product\11.2.0\dbhome_1\BIN\orannzsbb11.SYM does not match binary.
 Symbol TimeStamp=4cea6d1b, Module TimeStamp=4d6f3707 are different
Incident 4193 created, dump file: C:\ORACLE\diag\rdbms\test\test\incident\incdir_4193\test_ora_3796_i4193.trc
ORA-00600: internal error code, arguments: [qkebCreateConstantOpn1], [], [], [], [], [], [], [], [], [], [], []

* BLOCK CHECKING IS NOT DONE-Call Heap not initialized.
* Skip checking block dba=0x2402d02.
* BLOCK CHECKING IS NOT DONE-Call Heap not initialized.
* Skip checking block dba=0x340660f.
WAIT #386943464: nam='SQL*Net break/reset to client' ela= 2 driver id=1413697536 break?=1 p3=0 obj#=17988 tim=63752354884
WAIT #386943464: nam='SQL*Net break/reset to client' ela= 469 driver id=1413697536 break?=0 p3=0 obj#=17988 tim=63752355367
WAIT #386943464: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=17988 tim=63752355385
WAIT #386943464: nam='SQL*Net message from client' ela= 7198 driver id=1413697536 #bytes=1 p3=0 obj#=17988 tim=63752362607
WAIT #0: nam='ADR file lock' ela= 3  =0  =0  =0 obj#=17988 tim=63752362675
WAIT #0: nam='ADR file lock' ela= 67  =0  =0  =0 obj#=17988 tim=63752362763
WAIT #0: nam='ADR block file read' ela= 146  =0  =0  =0 obj#=17988 tim=63752363029
WAIT #0: nam='ADR block file write' ela= 392  =0  =0  =0 obj#=17988 tim=63752363449
XCTEND rlbk=1, rd_only=0, tim=63752364013
WAIT #0: nam='log file sync' ela= 115 buffer#=1552 sync scn=251585418 p3=0 obj#=17988 tim=63752364516
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=17988 tim=63752364548

Interesting, maybe?  I ran a test in an older version of the ERP package, also using Oracle Database 11.2.0.2.  My test did not generate an ORA-00600 error, but I did notice something that was a bit interesting.  There was not a single SQL statement similar to the following in my trace file, while the SQL statement was found in the trace file that was sent to me:

select binaryDefVal, lengthb(binaryDefVal) from ecol$ where tabobj# = :1 and colnum = :2

ECOL$? Anything found by Google?  OK, two articles, I will briefly quote one of the articles for dramatic effect:

“11G introduced a fast=true feature for adding columns with default values. In 11G when you want to add a not null column with a default value, the operation completes in the blink of an eye (if there are no locks on the table of course). Now it does not have to update all the rows, it just keeps the information as meta-data in the dictionary. So adding a new column becomes just a few dictionary operations.”

I suspect that the ERP upgrade script might have added non-NULL columns with default values… so let’s take a tour through Metalink (MOS) to see if anything interesting is found:

  • Doc ID 1301504.1: “ORA-00600: internal error code, arguments: [qkebCreateConstantOpn1] ON UPDATES ON TABLES WITH CONSTRAINTS”
  • Bug 12316092: “ORA-600 [QKEBCREATECONSTANTOPN1] AFTER ADDING NOT NULL COLUMN WITH DEFAULT”
  • Bug 12760255: “ORA-00600 INTERNAL ERROR CODE, ARGUMENTS [QKEBCREATECONSTANTOPN1] ON SELECT STAT”
  • Doc ID 8501439.8, Bug 8501439:” OERI[kghfrh:ds] / [kghfrempty:ds] / [17147] ORA-7445 [memcpy] with ANALYZE in a table with added column”
  • Doc ID 1106553.1: “Wrong Result For Added Column After Table Creation in 11g”
  • Bug 11865621: “MERGE ON TABLE WITH COL ADDED WHEN _ADD_COL_OPTIM_ENABLED=TRUE SPINS ON CPU”
  • Bug 10261680: “QUERY RETURNING WRONG RESULT WITH PARALLEL ENABLED”
  • Doc ID 10080167.8, Bug 10080167: “ORA-600 [15599] / dump [kghalf] from TRIGGER with WHEN clause”

OK, so I located through Metalink a couple of potential problems that might be related to the problem that was brought to my attention, some of which might be fixed in Oracle Database 11.2.0.3 or 11.2 (the first two seem to directly pertain to this issue).  It appears that quite a few of the bugs are triggered by the optimization (the fast=true reference in the above quote) that was introduced in Oracle Database 11.1.

What might be the work-around for this particular problem (mostly rough guesses at this point – pick one):

  • Wait for the release of Oracle Database 11.2.0.3 on the Windows platform… or 12.1.
  • Execute “ALTER SYSTEM SET “_ADD_COL_OPTIM_ENABLED”=FALSE;” before running the scripts that add the additional columns to the tables.
  • After running the ERP upgrade scripts, export the database, drop the database, create a new blank database, and then import the exported file.

Any other options?

If you look at the trace file output above, you might have noticed the following line:

Symbol file c:\Oracle\product\11.2.0\dbhome_1\BIN\orannzsbb11.SYM does not match binary

I wonder if that message has any relevance to the problem? It is slightly interesting to find that Oracle Database 11.2.0.1 with patch 7 installed has a file by that name with a file date of April 8, 2011 (399KB in size) while 11.2.0.2 with patch 6 apparently has an older version with a file date of November 22, 2010 (395KB in size). Probably unrelated to the problem at hand, but still interesting that a more recent release offers an older version of a file. I wonder if that file date problem could be related (requires a My Oracle Support account):

Doc ID 1272490.1: “‘Symbol file oraclsra11.SYM does not match binary’ Reported In Trace File + ORA-600 / ORA-7445″





SESSION_CACHED_CURSORS – Possibly Interesting Details

21 07 2011

July 21, 2011

Have you ever wondered about the V$OPEN_CURSOR view, the SESSION_CACHED_CURSORS parameter, and the two session-level statistics “session cursor cache count” and “session cursor cache hits”?  I did after reading from two different sources that stated essentially that a larger shared pool would be required when the value for the SESSION_CACHED_CURSORS parameter is increased.  The shared pool? – but the session’s cursors are cached in the UGA, which is typically in the PGA (unless shared server is used), and as far as I am aware the PGA is not in the shared pool.

So, what do we (think that we) know about the session cached cursors?

  • The per session limit for the number of cached cursors is specified by the SESSION_CACHED_CURSORS parameter.
  • Prior to the release of the Oracle Database 9.2.0.5 patchset the OPEN_CURSORS parameter controlled the number of cached cursors for PL/SQL execution, and as of 9.2.0.5 the SESSION_CACHED_CURSORS parameter controls the number of PL/SQL cursors that are cached per session (source).
  • In recent Oracle Database release versions the SESSION_CACHED_CURSORS parameter defaults to a value of 50.
  • Assuming that the SESSION_CACHED_CURSORS parameter is set to a value greater than 0, a SQL statement that is executed three times in the same session will be added to that session’s cursor cache and will remain open, even when explicitly closed by the session.
  • Starting in Oracle Database 11.1, if a 10046 trace is enabled for a session and a cursor is closed, a CLOSE # line will be written to the 10046 trace file, with the type= parameter indicating whether or not the cursor was added to the session cursor cache (and was thus actually not closed).
  • In V$MYSTAT, the session-level “session cursor cache count” statistic indicates the number of cursors that are cached for the current session, while the “session cursor cached hits” statistic indicates the number of times the current session has accessed those cached cursors.
  • V$OPEN_CURSOR shows the cursors that are currently open for all connected sessions.  Those cursors that are in the session cursor cache will also appear in V$OPEN_CURSOR.

The above bullet points are probably common knowledge, but is it all true?

Let’s check the Oracle Database 11.2 documentation for V$OPEN_CURSOR:

“V$OPEN_CURSOR lists cursors that each user session currently has opened and parsed, or cached.”

Nothing out of the ordinary with the above quote – it seems to be well aligned with the last of the above bullet points.

Let’s check the Oracle Database 11.2 documentation for SESSION_CACHED_CURSORS:

Default value: 50

“SESSION_CACHED_CURSORS specifies the number of session cursors to cache. Repeated parse calls of the same SQL (including recursive SQL) or PL/SQL statement cause the session cursor for that statement to be moved into the session cursor cache. Subsequent parse calls will find the cursor in the cache and do not need to reopen the cursor. Oracle uses a least recently used algorithm to remove entries in the session cursor cache to make room for new entries when needed.”

The above confirms bullet points one and three that were listed above, and almost bullet point two.

Let’s check the behavior changes listed for Oracle Database 11.2 in the documentation library:

“Starting with Oracle Database 10g Release 1 (10.1), the number of cached cursors is determined by the SESSION_CACHED_CURSORS initialization parameter. In previous Oracle Database releases, the number of SQL cursors cached by PL/SQL was determined by the OPEN_CURSORS initialization parameter.”

Although the above quote states Oracle Database 10.1 rather than 9.2.0.5, the quote confirms the change mentioned in the second of the above bullet points.

Let’s take a look at part of the Performance Tuning Guide from the 11.2 documentation set:

“Oracle checks the library cache to determine whether more than three parse requests have been issued on a given statement. If so, then Oracle assumes that the session cursor associated with the statement should be cached and moves the cursor into the session cursor cache. Subsequent requests to parse that SQL statement by the same session then find the cursor in the session cursor cache.”

Although the above states that a SQL statement must be parsed more than three times before it is added to the session cursor cache rather than executed three times, the quote basically confirms the fourth of the above bullet points.

Checking the statistic descriptions for Oracle Database 11.2:

session cursor cache count: Total number of cursors cached. This statistic is incremented only if SESSION_CACHED_CURSORS > 0. This statistic is the most useful in V$SESSTAT. If the value for this statistic in V$SESSTAT is close to the setting of the SESSION_CACHED_CURSORS parameter, the value of the parameter should be increased.

session cursor cache hits: Number of hits in the session cursor cache. A hit means that the SQL statement did not have to be reparsed. Subtract this statistic from “parse count (total)” to determine the real number of parses that occurred.”

The above quote seems to confirm the second to the last of the above bullet points.

Everyone happy, or should we test?

We need a table for a bit of experimentation, and we might as well flush the shared pool too:

CREATE TABLE T4 AS
SELECT
  *
FROM
  ALL_OBJECTS
WHERE
  ROWNUM<=10;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T4') 

ALTER SYSTEM FLUSH SHARED_POOL;

Now we need some sort of an elegant way to test the bulleted items that are listed at the start of this article.  Of course, a VBS script that is executed on the poor Windows client computer that is sitting under the finger smudged iPad is the perfect way to run a test.  In the script below replace MyUsername with a valid username for your database, replace MyPassword with the password for that user, and replace MyDatabase with the database SID as it appears in the TNSNAMES.ORA file.  The script performs the following actions:

  1. Connects to the database
  2. Determines the SID and SERIAL# for the session and writes those values to the C:\SessionCursorCache.txt text file.
  3. Enables a 10046 trace at level 1 (minimal detail with no wait events)
  4. Writes the session’s current values for the “session cursor cache hits” and “session cursor cache count” to the text file.
  5. Writes to the text file all SQL statements from V$OPEN_CURSOR where the SID matches the SID for the current session.
  6. Opens two cursors for the SQL statement “SELECT * FROM T4″
  7. Writes the session’s current values for the “session cursor cache hits” and “session cursor cache count” to the text file.  This should indicate if opening the cursors in step 6 triggered a hit on the cached cursors.
  8. Retrieves all rows from the two cursors and explicitly closes those cursors (potentially alternating between fetches from the two cursors if table T4 contained more than 1,000 rows).
  9. Repeat steps 4 through 8 two more times to see how repeated executions affect the statistics and the cursors that are cached.
  10. Disconnects from the database.

The script follows (script download, save with .vbs extension SessionCachedCursorsTest.vbs):

Dim strSQL
Dim strSQL2
Dim strSQL3
Dim strUsername
Dim strPassword
Dim strDatabase
Dim snpData
Dim snpData2
Dim snpDataCursorCache
Dim snpDataOpenSQL
Dim snpDataSID
Dim dbDatabase
Dim lngCnt
Dim intPass
Dim objFSO
Dim objFile

Set objFSO = CreateObject("Scripting.FileSystemObject")
Set objFile=objFSO.CreateTextFile("C:\SessionCursorCache.txt", True)

Set snpData = CreateObject("ADODB.Recordset")
Set snpData2 = CreateObject("ADODB.Recordset")
Set snpDataCursorCache = CreateObject("ADODB.Recordset")
Set snpDataOpenSQL = CreateObject("ADODB.Recordset")
Set snpDataSID = CreateObject("ADODB.Recordset")
Set dbDatabase = CreateObject("ADODB.Connection")

strUsername = "MyUsername"
strPassword = "MyPassword"
strDatabase = "MyDatabase"
dbDatabase.ConnectionString = "Provider=OraOLEDB.Oracle;Data Source=" & strDatabase & ";User ID=" & strUsername & ";Password=" & strPassword & ";FetchSize=5000;"

dbDatabase.Open

strSQL = "SELECT" & VBCrLf
strSQL = strSQL & "  S.SID," & VBCrLf
strSQL = strSQL & "  S.SERIAL# SERIALN" & VBCrLf
strSQL = strSQL & "FROM" & VBCrLf
strSQL = strSQL & "  V$SESSION S," & VBCrLf
strSQL = strSQL & "  (SELECT" & VBCrLf
strSQL = strSQL & "    SID" & VBCrLf
strSQL = strSQL & "  FROM" & VBCrLf
strSQL = strSQL & "    V$MYSTAT" & VBCrLf
strSQL = strSQL & "  WHERE" & VBCrLf
strSQL = strSQL & "    ROWNUM=1) M" & VBCrLf
strSQL = strSQL & "WHERE" & VBCrLf
strSQL = strSQL & "  S.SID=M.SID" & VBCrLf

snpDataSID.Open strSQL, dbDatabase
If snpDataSID.State = 1 Then
  Do While Not(snpDataSID.EOF)
    objFile.Write "SID: " & snpDataSID("sid") & ",  SERIAL#: " & snpDataSID("serialn") & VBCrLf
    snpDataSID.MoveNext
  Loop
  snpDataSID.Close
  objFile.Write " " & VBCrLf
End If

dbDatabase.Execute "ALTER SESSION SET TRACEFILE_IDENTIFIER = 'SessionCursorCache'"
dbDatabase.Execute "ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 1'"

strSQL2 = "SELECT" & VBCrLf
strSQL2 = strSQL2 & "  SN.NAME STAT_NAME," & VBCrLf
strSQL2 = strSQL2 & "  M.VALUE" & VBCrLf
strSQL2 = strSQL2 & "FROM" & VBCrLf
strSQL2 = strSQL2 & "  V$MYSTAT M," & VBCrLf
strSQL2 = strSQL2 & "  V$STATNAME SN" & VBCrLf
strSQL2 = strSQL2 & "WHERE" & VBCrLf
strSQL2 = strSQL2 & "  SN.NAME IN ('session cursor cache hits','session cursor cache count')" & VBCrLf
strSQL2 = strSQL2 & "  AND SN.STATISTIC#=M.STATISTIC#" & VBCrLf
strSQL2 = strSQL2 & "ORDER BY" & VBCrLf
strSQL2 = strSQL2 & "  SN.NAME"

strSQL3 = "SELECT" & VBCrLf
strSQL3 = strSQL3 & "  SQL_TEXT" & VBCrLf
strSQL3 = strSQL3 & "FROM" & VBCrLf
strSQL3 = strSQL3 & "  V$OPEN_CURSOR" & VBCrLf
strSQL3 = strSQL3 & "WHERE" & VBCrLf
strSQL3 = strSQL3 & "  SID=" & VBCrLf
strSQL3 = strSQL3 & "    (SELECT" & VBCrLf
strSQL3 = strSQL3 & "       SID" & VBCrLf
strSQL3 = strSQL3 & "     FROM" & VBCrLf
strSQL3 = strSQL3 & "       V$MYSTAT" & VBCrLf
strSQL3 = strSQL3 & "     WHERE" & VBCrLf
strSQL3 = strSQL3 & "       ROWNUM=1)" & VBCrLf
strSQL3 = strSQL3 & "ORDER BY" & VBCrLf
strSQL3 = strSQL3 & "  SQL_TEXT"

For intPass = 1 to 3
snpDataCursorCache.Open strSQL2, dbDatabase
If snpDataCursorCache.State = 1 Then
  objFile.Write "Before Pass #" & intPass & VBCrLf
  Do While Not(snpDataCursorCache.EOF)
    objFile.Write snpDataCursorCache("stat_name") & " " & snpDataCursorCache("value") & VBCrLf
    snpDataCursorCache.MoveNext
  Loop
  snpDataCursorCache.Close
  objFile.Write " " & VBCrLf
End If

snpDataOpenSQL.Open strSQL3, dbDatabase
lngCnt = 0
If snpDataOpenSQL.State = 1 Then
  Do While Not(snpDataOpenSQL.EOF)
    lngCnt = lngCnt + 1
    objFile.Write lngCnt & "  " & snpDataOpenSQL("sql_text") & VBCrLf
    snpDataOpenSQL.MoveNext
  Loop
  snpDataOpenSQL.Close
  objFile.Write " " & VBCrLf
End If

strSQL = "SELECT * FROM T4"
snpData.Open strSQL, dbDatabase
snpData2.Open strSQL, dbDatabase
snpDataCursorCache.Open strSQL2, dbDatabase
If snpDataCursorCache.State = 1 Then
  objFile.Write "After Open Pass #" & intPass & VBCrLf
  Do While Not(snpDataCursorCache.EOF)
    objFile.Write snpDataCursorCache("stat_name") & " " & snpDataCursorCache("value") & VBCrLf
    snpDataCursorCache.MoveNext
  Loop
  snpDataCursorCache.Close
  objFile.Write " " & VBCrLf
End If

lngCnt = 0
If snpData.State = 1 Then
  Do While Not(snpData.EOF)
    Do While (lngCnt < 1000) and Not(snpData.EOF)
      lngCnt = lngCnt + 1
      snpData.MoveNext
    Loop
    lngCnt = 0

    Do While (lngCnt < 1000) and Not(snpData2.EOF)
      lngCnt = lngCnt + 1
      snpData2.MoveNext
    Loop
    lngCnt = 0
  Loop
End If

snpData.Close
snpData2.Close

Next

dbDatabase.Execute "ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF'"
objFile.Close

Set snpData = Nothing
Set snpData2 = Nothing
Set snpDataCursorCache = Nothing
Set snpDataOpenSQL = Nothing
Set snpDataSID = Nothing

dbDatabase.Close
Set dbDatabase = Nothing
Set objFile = Nothing
Set objFSO = Nothing

If you save the script as SessionCachedCursorsTest.vbs you can execute it from a Windows command line with the following command:

CSCRIPT SessionCachedCursorsTest.vbs

The script will generate a file named C:\SessionCursorCache.txt (if User Access Control is enabled on the Windows computer, you will need to modify the script to create the file in a different location).  What might you find in the generated file?  This is what I saw after the script ran shortly after flushing the shared pool (64 bit Oracle Database 11.2.0.2):

SID: 66,  SERIAL#: 7863

Before Pass #1
session cursor cache count 49
session cursor cache hits 240

1  SELECT    SQL_TEXT  FROM    V$OPEN_CURSOR  WHERE    SID=   
2  insert into sys.aud$( sessionid,entryid,statement,ntimestamp
3  select /*+ rule */ bucket, endpoint, col#, epvalue from hist
4  select /*+ rule */ bucket, endpoint, col#, epvalue from hist
5  select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt,
6  select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt,
7  select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt,
8  select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
9  select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
10  select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
11  select col#,intcol#,charsetid,charsetform from col$ where ob
12  select col#,intcol#,charsetid,charsetform from col$ where ob
13  select col#,intcol#,charsetid,charsetform from col$ where ob
14  select col#,intcol#,ntab# from ntab$ where obj#=:1 order by
15  select col#,intcol#,ntab# from ntab$ where obj#=:1 order by
16  select col#,intcol#,ntab# from ntab$ where obj#=:1 order by
17  select col#,intcol#,reftyp,stabid,expctoid from refcon$ wher
18  select col#,intcol#,reftyp,stabid,expctoid from refcon$ wher
19  select col#,intcol#,reftyp,stabid,expctoid from refcon$ wher
20  select col#,intcol#,toid,version#,packed,intcols,intcol#s,fl
21  select col#,intcol#,toid,version#,packed,intcols,intcol#s,fl
22  select col#,intcol#,toid,version#,packed,intcols,intcol#s,fl
23  select cols,audit$,textlength,intcols,property,flags,rowid f
24  select cols,audit$,textlength,intcols,property,flags,rowid f
25  select con#,obj#,rcon#,enabled,nvl(defer,0),spare2,spare3 fr
26  select con#,obj#,rcon#,enabled,nvl(defer,0),spare2,spare3 fr
27  select con#,type#,condlength,intcols,robj#,rcon#,match#,refa
28  select con#,type#,condlength,intcols,robj#,rcon#,match#,refa
29  select distinct(-privilege#),nvl(option$,0) from sysauth$ wh
30  select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0
31  select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0
32  select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0
33  select intcol#, toid, version#, intcols, intcol#s, flags, sy
34  select intcol#, toid, version#, intcols, intcol#s, flags, sy
35  select intcol#, toid, version#, intcols, intcol#s, flags, sy
36  select intcol#,type,flags,lobcol,objcol,extracol,schemaoid,
37  select intcol#,type,flags,lobcol,objcol,extracol,schemaoid,
38  select intcol#,type,flags,lobcol,objcol,extracol,schemaoid,
39  select l.col#, l.intcol#, l.lobj#, l.ind#, l.ts#, l.file#, l
40  select name,intcol#,segcol#,type#,length,nvl(precision#,0),d
41  select name,intcol#,segcol#,type#,length,nvl(precision#,0),d
42  select node,owner,name from syn$ where obj#=:1
43  select node,owner,name from syn$ where obj#=:1
44  select obj#,type#,ctime,mtime,stime, status, dataobj#, flags
45  select obj#,type#,ctime,mtime,stime, status, dataobj#, flags
46  select order#,columns,types from access$ where d_obj#=:1
47  select owner#,name,namespace,remoteowner,linkname,p_timestam
48  select rowcnt, blkcnt, empcnt, avgspc, chncnt, avgrln, analy
49  select text from view$ where rowid=:1
50  select text from view$ where rowid=:1
51  select timestamp, flags from fixed_obj$ where obj#=:1
52  select timestamp, flags from fixed_obj$ where obj#=:1

After Open Pass #1
session cursor cache count 49
session cursor cache hits 279

Before Pass #2
session cursor cache count 49
session cursor cache hits 279

1  SELECT    SN.NAME STAT_NAME,    M.VALUE  FROM    V$MYSTAT M,
2  SELECT    SQL_TEXT  FROM    V$OPEN_CURSOR  WHERE    SID=   
3  insert into sys.aud$( sessionid,entryid,statement,ntimestamp
4  select /*+ rule */ bucket, endpoint, col#, epvalue from hist
5  select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt,
6  select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt,
7  select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt,
8  select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
9  select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
10  select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
11  select col#,intcol#,charsetid,charsetform from col$ where ob
12  select col#,intcol#,charsetid,charsetform from col$ where ob
13  select col#,intcol#,charsetid,charsetform from col$ where ob
14  select col#,intcol#,ntab# from ntab$ where obj#=:1 order by
15  select col#,intcol#,ntab# from ntab$ where obj#=:1 order by
16  select col#,intcol#,reftyp,stabid,expctoid from refcon$ wher
17  select col#,intcol#,reftyp,stabid,expctoid from refcon$ wher
18  select col#,intcol#,toid,version#,packed,intcols,intcol#s,fl
19  select col#,intcol#,toid,version#,packed,intcols,intcol#s,fl
20  select cols,audit$,textlength,intcols,property,flags,rowid f
21  select cols,audit$,textlength,intcols,property,flags,rowid f
22  select con#,obj#,rcon#,enabled,nvl(defer,0),spare2,spare3 fr
23  select con#,obj#,rcon#,enabled,nvl(defer,0),spare2,spare3 fr
24  select con#,obj#,rcon#,enabled,nvl(defer,0),spare2,spare3 fr
25  select con#,type#,condlength,intcols,robj#,rcon#,match#,refa
26  select con#,type#,condlength,intcols,robj#,rcon#,match#,refa
27  select con#,type#,condlength,intcols,robj#,rcon#,match#,refa
28  select distinct(-privilege#),nvl(option$,0) from sysauth$ wh
29  select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0
30  select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0
31  select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0
32  select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.fla
33  select intcol#, toid, version#, intcols, intcol#s, flags, sy
34  select intcol#, toid, version#, intcols, intcol#s, flags, sy
35  select intcol#,nvl(pos#,0),col#,nvl(spare1,0) from ccol$ whe
36  select intcol#,type,flags,lobcol,objcol,extracol,schemaoid,
37  select intcol#,type,flags,lobcol,objcol,extracol,schemaoid,
38  select intcol#,type,flags,lobcol,objcol,extracol,schemaoid,
39  select name,intcol#,segcol#,type#,length,nvl(precision#,0),d
40  select name,intcol#,segcol#,type#,length,nvl(precision#,0),d
41  select name,intcol#,segcol#,type#,length,nvl(precision#,0),d
42  select node,owner,name from syn$ where obj#=:1
43  select node,owner,name from syn$ where obj#=:1
44  select obj#,type#,ctime,mtime,stime, status, dataobj#, flags
45  select obj#,type#,ctime,mtime,stime, status, dataobj#, flags
46  select obj#,type#,ctime,mtime,stime, status, dataobj#, flags
47  select order#,columns,types from access$ where d_obj#=:1
48  select owner#,name,namespace,remoteowner,linkname,p_timestam
49  select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t
50  select text from view$ where rowid=:1
51  select timestamp, flags from fixed_obj$ where obj#=:1
52  select type#,blocks,extents,minexts,maxexts,extsize,extpct,u

After Open Pass #2
session cursor cache count 50
session cursor cache hits 280

Before Pass #3
session cursor cache count 50
session cursor cache hits 281

1  SELECT    SN.NAME STAT_NAME,    M.VALUE  FROM    V$MYSTAT M,
2  SELECT    SQL_TEXT  FROM    V$OPEN_CURSOR  WHERE    SID=   
3  SELECT * FROM T4
4  SELECT * FROM T4
5  insert into sys.aud$( sessionid,entryid,statement,ntimestamp
6  select /*+ rule */ bucket, endpoint, col#, epvalue from hist
7  select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt,
8  select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt,
9  select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt,
10  select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
11  select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
12  select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
13  select col#,intcol#,charsetid,charsetform from col$ where ob
14  select col#,intcol#,charsetid,charsetform from col$ where ob
15  select col#,intcol#,ntab# from ntab$ where obj#=:1 order by
16  select col#,intcol#,ntab# from ntab$ where obj#=:1 order by
17  select col#,intcol#,reftyp,stabid,expctoid from refcon$ wher
18  select col#,intcol#,reftyp,stabid,expctoid from refcon$ wher
19  select col#,intcol#,toid,version#,packed,intcols,intcol#s,fl
20  select col#,intcol#,toid,version#,packed,intcols,intcol#s,fl
21  select cols,audit$,textlength,intcols,property,flags,rowid f
22  select cols,audit$,textlength,intcols,property,flags,rowid f
23  select con#,obj#,rcon#,enabled,nvl(defer,0),spare2,spare3 fr
24  select con#,obj#,rcon#,enabled,nvl(defer,0),spare2,spare3 fr
25  select con#,obj#,rcon#,enabled,nvl(defer,0),spare2,spare3 fr
26  select con#,type#,condlength,intcols,robj#,rcon#,match#,refa
27  select con#,type#,condlength,intcols,robj#,rcon#,match#,refa
28  select con#,type#,condlength,intcols,robj#,rcon#,match#,refa
29  select distinct(-privilege#),nvl(option$,0) from sysauth$ wh
30  select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0
31  select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0
32  select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0
33  select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.fla
34  select intcol#, toid, version#, intcols, intcol#s, flags, sy
35  select intcol#, toid, version#, intcols, intcol#s, flags, sy
36  select intcol#,nvl(pos#,0),col#,nvl(spare1,0) from ccol$ whe
37  select intcol#,type,flags,lobcol,objcol,extracol,schemaoid,
38  select intcol#,type,flags,lobcol,objcol,extracol,schemaoid,
39  select name,intcol#,segcol#,type#,length,nvl(precision#,0),d
40  select name,intcol#,segcol#,type#,length,nvl(precision#,0),d
41  select name,intcol#,segcol#,type#,length,nvl(precision#,0),d
42  select node,owner,name from syn$ where obj#=:1
43  select node,owner,name from syn$ where obj#=:1
44  select obj#,type#,ctime,mtime,stime, status, dataobj#, flags
45  select obj#,type#,ctime,mtime,stime, status, dataobj#, flags
46  select obj#,type#,ctime,mtime,stime, status, dataobj#, flags
47  select order#,columns,types from access$ where d_obj#=:1
48  select owner#,name,namespace,remoteowner,linkname,p_timestam
49  select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t
50  select text from view$ where rowid=:1
51  select timestamp, flags from fixed_obj$ where obj#=:1
52  select type#,blocks,extents,minexts,maxexts,extsize,extpct,u

After Open Pass #3
session cursor cache count 50
session cursor cache hits 284

Reading the above, before our newly created session even selected from table T4, the statistics indicate that somehow there were already 49 cursors in that session’s cursor cache (many of the SQL statements appeared multiple times) and there were already 240 hits on those cached cursors.  Did this session really perform more than 387 (49*3 + 240) executions of SQL statements before our first selection from T4, or does V$OPEN_CURSOR perform differently than described in the documentation?  By the time the two cursors selecting from T4 were opened, the number of cursor cache hits jumped by 39.  After the two cursors were closed (Before Pass #2) we are able to confirm that the select from table T4 was not added to the session cursor cache and there were still 49 cursors in that cache.

On the second pass, we are able to confirm that the select from table T4 is not yet in the session cursor cache.  Immediately after the two cursors selected from table T2 were opened, we see that the session experienced one more cursor cache hit, and another cursor was added to the session cursor cache.

At the start of the third pass, we see that our select from T2 is now in the session cursor cache, not once, but twice, there were 50 cursors in the session cursor cache, and there was one more session cursor cache hit.  When the two cursors selecting from table T4 were opened, we see that the session experienced three more cursor cache hits.

Let’s take a quick look at portions of the 10046 trace file that are related to the SQL statements that were executed by our script (just primarily focusing on the parse and close calls):

PARSING IN CURSOR #429272512 len=212 dep=0 uid=64 oct=3 lid=64 tim=2769436992465 hv=3255970530 ad='3ed509198' sqlid='c2a4dv3114ar2'
SELECT
  SN.NAME STAT_NAME,
  M.VALUE
FROM
  V$MYSTAT M,
  V$STATNAME SN
WHERE
  SN.NAME IN ('session cursor cache hits','session cursor cache count')
  AND SN.STATISTIC#=M.STATISTIC#
ORDER BY
  SN.NAME
END OF STMT
CLOSE #429272512:c=0,e=16,dep=0,type=0,tim=2769436996834

PARSING IN CURSOR #429272512 len=161 dep=0 uid=64 oct=3 lid=64 tim=2769437006931 hv=3838443513 ad='3eb511630' sqlid='babcumbkcmzzt'
SELECT
  SQL_TEXT
FROM
  V$OPEN_CURSOR
WHERE
  SID=
    (SELECT
       SID
     FROM
       V$MYSTAT
     WHERE
       ROWNUM=1)
ORDER BY
  SQL_TEXT
END OF STMT
CLOSE #429272512:c=0,e=19,dep=0,type=0,tim=2769437013363

PARSING IN CURSOR #429272512 len=16 dep=0 uid=64 oct=3 lid=64 tim=2769437025761 hv=1886046789 ad='3eba6b810' sqlid='49fgb3ts6pkk5'
SELECT * FROM T4
END OF STMT

PARSING IN CURSOR #441175000 len=16 dep=0 uid=64 oct=3 lid=64 tim=2769437031138 hv=1886046789 ad='3eba6b810' sqlid='49fgb3ts6pkk5'
SELECT * FROM T4
END OF STMT

PARSING IN CURSOR #440835720 len=212 dep=0 uid=64 oct=3 lid=64 tim=2769437036683 hv=3255970530 ad='3ed509198' sqlid='c2a4dv3114ar2'
SELECT
  SN.NAME STAT_NAME,
  M.VALUE
FROM
  V$MYSTAT M,
  V$STATNAME SN
WHERE
  SN.NAME IN ('session cursor cache hits','session cursor cache count')
  AND SN.STATISTIC#=M.STATISTIC#
ORDER BY
  SN.NAME
END OF STMT

CLOSE #441175000:c=0,e=11,dep=0,type=0,tim=2769437040272
CLOSE #429272512:c=0,e=8,dep=0,type=0,tim=2769437040299
CLOSE #440835720:c=0,e=6,dep=0,type=0,tim=2769437040318
=====================
PARSING IN CURSOR #429272512 len=212 dep=0 uid=64 oct=3 lid=64 tim=2769437040366 hv=3255970530 ad='3ed509198' sqlid='c2a4dv3114ar2'
SELECT
  SN.NAME STAT_NAME,
  M.VALUE
FROM
  V$MYSTAT M,
  V$STATNAME SN
WHERE
  SN.NAME IN ('session cursor cache hits','session cursor cache count')
  AND SN.STATISTIC#=M.STATISTIC#
ORDER BY
  SN.NAME
END OF STMT

CLOSE #429272512:c=0,e=13,dep=0,type=1,tim=2769437042471
=====================
PARSING IN CURSOR #441175000 len=161 dep=0 uid=64 oct=3 lid=64 tim=2769437042547 hv=3838443513 ad='3eb511630' sqlid='babcumbkcmzzt'
SELECT
  SQL_TEXT
FROM
  V$OPEN_CURSOR
WHERE
  SID=
    (SELECT
       SID
     FROM
       V$MYSTAT
     WHERE
       ROWNUM=1)
ORDER BY
  SQL_TEXT
END OF STMT
CLOSE #441175000:c=0,e=19,dep=0,type=0,tim=2769437051038
=====================
PARSING IN CURSOR #441175000 len=16 dep=0 uid=64 oct=3 lid=64 tim=2769437051137 hv=1886046789 ad='3eba6b810' sqlid='49fgb3ts6pkk5'
SELECT * FROM T4
END OF STMT

PARSING IN CURSOR #440600648 len=16 dep=0 uid=64 oct=3 lid=64 tim=2769437053863 hv=1886046789 ad='3eba6b810' sqlid='49fgb3ts6pkk5'
SELECT * FROM T4
END OF STMT

CLOSE #440600648:c=0,e=10,dep=0,type=1,tim=2769437060397
CLOSE #441175000:c=0,e=14,dep=0,type=1,tim=2769437060431
CLOSE #429272512:c=0,e=14,dep=0,type=3,tim=2769437060459
PARSE #429272512:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1338012530,tim=2769437060499
CLOSE #429272512:c=0,e=31,dep=0,type=3,tim=2769437062969
=====================
PARSING IN CURSOR #440639688 len=161 dep=0 uid=64 oct=3 lid=64 tim=2769437063067 hv=3838443513 ad='3eb511630' sqlid='babcumbkcmzzt'
SELECT
  SQL_TEXT
FROM
  V$OPEN_CURSOR
WHERE
  SID=
    (SELECT
       SID
     FROM
       V$MYSTAT
     WHERE
       ROWNUM=1)
ORDER BY
  SQL_TEXT
END OF STMT
CLOSE #440639688:c=0,e=20,dep=0,type=1,tim=2769437071488

PARSE #440600648:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2560505625,tim=2769437071547
PARSE #441175000:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2560505625,tim=2769437073533
PARSE #429272512:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1338012530,tim=2769437076014
CLOSE #441175000:c=0,e=7,dep=0,type=3,tim=2769437079257
CLOSE #440600648:c=0,e=4,dep=0,type=3,tim=2769437079281

What does the above show?  Notice that the numbers following type= on the CLOSE lines seem to change – what do those numbers mean?  If we refer to page 284 of the book “Secrets of the Oracle Database“, we find the following information:

type=0: cursor is actually closed.
type=1: cursor is added to the session cursor cache without pushing an existing cursor out of the session cursor cache.
type=2: cursor is added to the session cursor cache, in the process pushing an existing cursor out of the session cursor cache.
type=3: cursor was already in the session cursor cache

So, the above indicates that the cursors are actually added to the session cursor cache NOT during a parse call, but instead when the cursor is attempted to be explicitly closed.  The documentation describing the SESSION_CACHED_CURSORS parameter, referenced above, appears to be misleading.  It is a bit odd that our select from T4 was added to the session cursor cache twice.  It is also a bit odd that the large cursor numbers, introduced with Oracle Database 11.2.0.2 that I understand to represent the address of the cursor, were reused for different SQL statements (this might have significance in a later blog article).

Just for fun, let’s re-execute the VBS script:

CSCRIPT SessionCachedCursorsTest.vbs

This is now the script’s output:

SID: 192,  SERIAL#: 693

Before Pass #1
session cursor cache count 2
session cursor cache hits 1

1  SELECT    SN.NAME STAT_NAME,    M.VALUE  FROM    V$MYSTAT M,
2  SELECT    SQL_TEXT  FROM    V$OPEN_CURSOR  WHERE    SID=   
3  insert into sys.aud$( sessionid,entryid,statement,ntimestamp
4  select /*+ connect_by_filtering */ privilege#,level from sys
5  select privilege# from sysauth$ where (grantee#=:1 or grante

After Open Pass #1
session cursor cache count 4
session cursor cache hits 2

Before Pass #2
session cursor cache count 6
session cursor cache hits 3

1  SELECT    SN.NAME STAT_NAME,    M.VALUE  FROM    V$MYSTAT M,
2  SELECT    SQL_TEXT  FROM    V$OPEN_CURSOR  WHERE    SID=   
3  SELECT * FROM T4
4  SELECT * FROM T4
5  insert into sys.aud$( sessionid,entryid,statement,ntimestamp
6  select /*+ connect_by_filtering */ privilege#,level from sys
7  select privilege# from sysauth$ where (grantee#=:1 or grante

After Open Pass #2
session cursor cache count 6
session cursor cache hits 7

Before Pass #3
session cursor cache count 6
session cursor cache hits 8

1  SELECT    SN.NAME STAT_NAME,    M.VALUE  FROM    V$MYSTAT M,
2  SELECT    SQL_TEXT  FROM    V$OPEN_CURSOR  WHERE    SID=   
3  SELECT * FROM T4
4  SELECT * FROM T4
5  insert into sys.aud$( sessionid,entryid,statement,ntimestamp
6  select /*+ connect_by_filtering */ privilege#,level from sys
7  select privilege# from sysauth$ where (grantee#=:1 or grante

After Open Pass #3
session cursor cache count 6
session cursor cache hits 12

In the above, you will likely first notice that the SID and SERIAL# for our newly created session is not the same as it was earlier.  At the start of the output, before the first execution of the select from T4, we see that there were two cursors in the session’s cursor cache, and one hit on one of those two cursors – quite a change from the first execution of the script.  Immediately after opening cursors that selected from T4 we see that there were 4 cursors in the session cursor count, and 2 hits on those cursors.

Now another big change before the start of the second pass, we see that there were 6 cursors in the session cursor cache, including two selects from T4 –  previously, those cursors were added to the session cursor cache just before the start of the third pass.  After opening the two cursors selecting from T4, there were 4 more hits on the session cursor cache.

So, what are the apparent take-aways from this test case:

  • After flushing the shared pool a session’s cursor cache may contain a large number of SQL statements, duplicated in some cases, that may have only been executed a single time by the session at a depth greater than 0 (as indicated in a 10046 trace file).
  • After a SQL statement is parsed and closed 3 times the SQL statement is eligible for the session cursor cache when the SQL statement is closed for the third time.
  • If a SQL statement was previously parsed and closed 3 times by another session, the SQL statement is eligible for a different session’s cursor cache the first time that a cursor with that SQL statement is closed in the session.
  • Oracle Database 11.2.0.2’s huge cursor numbers that are written to 10046 trace files may be reused for entirely different SQL statements, and that does not necessarily indicate a cursor leak.
  • If a SQL statement is opened multiple times in a session without being closed between opens, it is quite possible that all of the cursors using the SQL statement will be added to the session cached cursors (the SQL statement will appear multiple times in V$OPEN_CURSOR) when those cursors are explicitly closed.

At this point, you are probably wondering what might happen when we open 12 cursors that select from T4.  Here is the modified script (script download, save with .vbs extension SessionCachedCursorsTest2.vbs):

Dim strSQL
Dim strSQL2
Dim strSQL3
Dim strUsername
Dim strPassword
Dim strDatabase
Dim snpData
Dim snpData2
Dim snpData3
Dim snpData4
Dim snpData5
Dim snpData6
Dim snpData7
Dim snpData8
Dim snpData9
Dim snpData10
Dim snpData11
Dim snpData12
Dim snpDataCursorCache
Dim snpDataOpenSQL
Dim snpDataSID
Dim dbDatabase
Dim lngCnt
Dim intPass
Dim objFSO
Dim objFile

Set objFSO = CreateObject("Scripting.FileSystemObject")
Set objFile=objFSO.CreateTextFile("C:\SessionCursorCache2.txt", True)

Set snpData = CreateObject("ADODB.Recordset")
Set snpData2 = CreateObject("ADODB.Recordset")
Set snpData3 = CreateObject("ADODB.Recordset")
Set snpData4 = CreateObject("ADODB.Recordset")
Set snpData5 = CreateObject("ADODB.Recordset")
Set snpData6 = CreateObject("ADODB.Recordset")
Set snpData7 = CreateObject("ADODB.Recordset")
Set snpData8 = CreateObject("ADODB.Recordset")
Set snpData9 = CreateObject("ADODB.Recordset")
Set snpData10 = CreateObject("ADODB.Recordset")
Set snpData11 = CreateObject("ADODB.Recordset")
Set snpData12 = CreateObject("ADODB.Recordset")
Set snpDataCursorCache = CreateObject("ADODB.Recordset")
Set snpDataOpenSQL = CreateObject("ADODB.Recordset")
Set snpDataSID = CreateObject("ADODB.Recordset")
Set dbDatabase = CreateObject("ADODB.Connection")

strUsername = "MyUsername"
strPassword = "MyPassword"
strDatabase = "MyDatabase"
dbDatabase.ConnectionString = "Provider=OraOLEDB.Oracle;Data Source=" & strDatabase & ";User ID=" & strUsername & ";Password=" & strPassword & ";FetchSize=5000;"

dbDatabase.Open

strSQL = "SELECT" & VBCrLf
strSQL = strSQL & "  S.SID," & VBCrLf
strSQL = strSQL & "  S.SERIAL# SERIALN" & VBCrLf
strSQL = strSQL & "FROM" & VBCrLf
strSQL = strSQL & "  V$SESSION S," & VBCrLf
strSQL = strSQL & "  (SELECT" & VBCrLf
strSQL = strSQL & "    SID" & VBCrLf
strSQL = strSQL & "  FROM" & VBCrLf
strSQL = strSQL & "    V$MYSTAT" & VBCrLf
strSQL = strSQL & "  WHERE" & VBCrLf
strSQL = strSQL & "    ROWNUM=1) M" & VBCrLf
strSQL = strSQL & "WHERE" & VBCrLf
strSQL = strSQL & "  S.SID=M.SID" & VBCrLf

snpDataSID.Open strSQL, dbDatabase
If snpDataSID.State = 1 Then
  Do While Not(snpDataSID.EOF)
    objFile.Write "SID: " & snpDataSID("sid") & ",  SERIAL#: " & snpDataSID("serialn") & VBCrLf
    snpDataSID.MoveNext
  Loop
  snpDataSID.Close
  objFile.Write " " & VBCrLf
End If

dbDatabase.Execute "ALTER SESSION SET TRACEFILE_IDENTIFIER = 'SessionCursorCache2'"
dbDatabase.Execute "ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 1'"

strSQL2 = "SELECT" & VBCrLf
strSQL2 = strSQL2 & "  SN.NAME STAT_NAME," & VBCrLf
strSQL2 = strSQL2 & "  M.VALUE" & VBCrLf
strSQL2 = strSQL2 & "FROM" & VBCrLf
strSQL2 = strSQL2 & "  V$MYSTAT M," & VBCrLf
strSQL2 = strSQL2 & "  V$STATNAME SN" & VBCrLf
strSQL2 = strSQL2 & "WHERE" & VBCrLf
strSQL2 = strSQL2 & "  SN.NAME IN ('session cursor cache hits','session cursor cache count')" & VBCrLf
strSQL2 = strSQL2 & "  AND SN.STATISTIC#=M.STATISTIC#" & VBCrLf
strSQL2 = strSQL2 & "ORDER BY" & VBCrLf
strSQL2 = strSQL2 & "  SN.NAME"

strSQL3 = "SELECT" & VBCrLf
strSQL3 = strSQL3 & "  SQL_TEXT" & VBCrLf
strSQL3 = strSQL3 & "FROM" & VBCrLf
strSQL3 = strSQL3 & "  V$OPEN_CURSOR" & VBCrLf
strSQL3 = strSQL3 & "WHERE" & VBCrLf
strSQL3 = strSQL3 & "  SID=" & VBCrLf
strSQL3 = strSQL3 & "    (SELECT" & VBCrLf
strSQL3 = strSQL3 & "       SID" & VBCrLf
strSQL3 = strSQL3 & "     FROM" & VBCrLf
strSQL3 = strSQL3 & "       V$MYSTAT" & VBCrLf
strSQL3 = strSQL3 & "     WHERE" & VBCrLf
strSQL3 = strSQL3 & "       ROWNUM=1)" & VBCrLf
strSQL3 = strSQL3 & "ORDER BY" & VBCrLf
strSQL3 = strSQL3 & "  SQL_TEXT"

For intPass = 1 to 3
snpDataCursorCache.Open strSQL2, dbDatabase
If snpDataCursorCache.State = 1 Then
  objFile.Write "Before Pass #" & intPass & VBCrLf
  Do While Not(snpDataCursorCache.EOF)
    objFile.Write snpDataCursorCache("stat_name") & " " & snpDataCursorCache("value") & VBCrLf
    snpDataCursorCache.MoveNext
  Loop
  snpDataCursorCache.Close
  objFile.Write " " & VBCrLf
End If

snpDataOpenSQL.Open strSQL3, dbDatabase
lngCnt = 0
If snpDataOpenSQL.State = 1 Then
  Do While Not(snpDataOpenSQL.EOF)
    lngCnt = lngCnt + 1
    objFile.Write lngCnt & "  " & snpDataOpenSQL("sql_text") & VBCrLf
    snpDataOpenSQL.MoveNext
  Loop
  snpDataOpenSQL.Close
  objFile.Write " " & VBCrLf
End If

strSQL = "SELECT * FROM T4"
snpData.Open strSQL, dbDatabase
snpData2.Open strSQL, dbDatabase
snpData3.Open strSQL, dbDatabase
snpData4.Open strSQL, dbDatabase
snpData5.Open strSQL, dbDatabase
snpData6.Open strSQL, dbDatabase
snpData7.Open strSQL, dbDatabase
snpData8.Open strSQL, dbDatabase
snpData9.Open strSQL, dbDatabase
snpData10.Open strSQL, dbDatabase
snpData11.Open strSQL, dbDatabase
snpData12.Open strSQL, dbDatabase

snpDataCursorCache.Open strSQL2, dbDatabase
If snpDataCursorCache.State = 1 Then
  objFile.Write "After Open Pass #" & intPass & VBCrLf
  Do While Not(snpDataCursorCache.EOF)
    objFile.Write snpDataCursorCache("stat_name") & " " & snpDataCursorCache("value") & VBCrLf
    snpDataCursorCache.MoveNext
  Loop
  snpDataCursorCache.Close
  objFile.Write " " & VBCrLf
End If

lngCnt = 0
If snpData.State = 1 Then
  Do While Not(snpData.EOF)
    Do While (lngCnt < 1000) and Not(snpData.EOF)
      lngCnt = lngCnt + 1
      snpData.MoveNext
    Loop
    lngCnt = 0

    Do While (lngCnt < 1000) and Not(snpData2.EOF)
      lngCnt = lngCnt + 1
      snpData2.MoveNext
    Loop
    lngCnt = 0

    Do While (lngCnt < 1000) and Not(snpData3.EOF)
      lngCnt = lngCnt + 1
      snpData3.MoveNext
    Loop
    lngCnt = 0

    Do While (lngCnt < 1000) and Not(snpData4.EOF)
      lngCnt = lngCnt + 1
      snpData4.MoveNext
    Loop
    lngCnt = 0

    Do While (lngCnt < 1000) and Not(snpData5.EOF)
      lngCnt = lngCnt + 1
      snpData5.MoveNext
    Loop
    lngCnt = 0

    Do While (lngCnt < 1000) and Not(snpData6.EOF)
      lngCnt = lngCnt + 1
      snpData6.MoveNext
    Loop
    lngCnt = 0

    Do While (lngCnt < 1000) and Not(snpData7.EOF)
      lngCnt = lngCnt + 1
      snpData7.MoveNext
    Loop
    lngCnt = 0

    Do While (lngCnt < 1000) and Not(snpData8.EOF)
      lngCnt = lngCnt + 1
      snpData8.MoveNext
    Loop
    lngCnt = 0

    Do While (lngCnt < 1000) and Not(snpData9.EOF)
      lngCnt = lngCnt + 1
      snpData9.MoveNext
    Loop
    lngCnt = 0

    Do While (lngCnt < 1000) and Not(snpData10.EOF)
      lngCnt = lngCnt + 1
      snpData10.MoveNext
    Loop
    lngCnt = 0

    Do While (lngCnt < 1000) and Not(snpData11.EOF)
      lngCnt = lngCnt + 1
      snpData11.MoveNext
    Loop
    lngCnt = 0

    Do While (lngCnt < 1000) and Not(snpData12.EOF)
      lngCnt = lngCnt + 1
      snpData12.MoveNext
    Loop
    lngCnt = 0
  Loop
End If

snpData.Close
snpData2.Close
snpData3.Close
snpData4.Close
snpData5.Close
snpData6.Close
snpData7.Close
snpData8.Close
snpData9.Close
snpData10.Close
snpData11.Close
snpData12.Close

Next

dbDatabase.Execute "ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF'"
objFile.Close

Set snpData = Nothing
Set snpData2 = Nothing
Set snpData3 = Nothing
Set snpData4 = Nothing
Set snpData5 = Nothing
Set snpData6 = Nothing
Set snpData7 = Nothing
Set snpData8 = Nothing
Set snpData9 = Nothing
Set snpData10 = Nothing
Set snpData11 = Nothing
Set snpData12 = Nothing
Set snpDataCursorCache = Nothing
Set snpDataOpenSQL = Nothing
Set snpDataSID = Nothing

dbDatabase.Close
Set dbDatabase = Nothing
Set objFile = Nothing
Set objFSO = Nothing

The following shows the output that I received on the first execution (the shared pool was not flushed prior to executing the script):

SID: 159,  SERIAL#: 5853

Before Pass #1
session cursor cache count 7
session cursor cache hits 1

1  SELECT    S.SID,    S.SERIAL# SERIALN  FROM    V$SESSION S,
2  SELECT    SN.NAME STAT_NAME,    M.VALUE  FROM    V$MYSTAT M,
3  SELECT    SQL_TEXT  FROM    V$OPEN_CURSOR  WHERE    SID=   
4  SELECT PARAMETER, VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHE
5  insert into sys.aud$( sessionid,entryid,statement,ntimestamp
6  select /*+ connect_by_filtering */ privilege#,level from sys
7  select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_CONTEXT('U
8  select decode(failover_method, NULL, 0 , 'BASIC', 1, 'PRECON
9  select privilege# from sysauth$ where (grantee#=:1 or grante
10  select value$ from props$ where name = 'GLOBAL_DB_NAME'

After Open Pass #1
session cursor cache count 9
session cursor cache hits 2

Before Pass #2
session cursor cache count 21
session cursor cache hits 3

1  SELECT    S.SID,    S.SERIAL# SERIALN  FROM    V$SESSION S,
2  SELECT    SN.NAME STAT_NAME,    M.VALUE  FROM    V$MYSTAT M,
3  SELECT    SQL_TEXT  FROM    V$OPEN_CURSOR  WHERE    SID=   
4  SELECT * FROM T4
5  SELECT * FROM T4
6  SELECT * FROM T4
7  SELECT * FROM T4
8  SELECT * FROM T4
9  SELECT * FROM T4
10  SELECT * FROM T4
11  SELECT * FROM T4
12  SELECT * FROM T4
13  SELECT * FROM T4
14  SELECT * FROM T4
15  SELECT * FROM T4
16  SELECT PARAMETER, VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHE
17  insert into sys.aud$( sessionid,entryid,statement,ntimestamp
18  select /*+ connect_by_filtering */ privilege#,level from sys
19  select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_CONTEXT('U
20  select decode(failover_method, NULL, 0 , 'BASIC', 1, 'PRECON
21  select privilege# from sysauth$ where (grantee#=:1 or grante
22  select value$ from props$ where name = 'GLOBAL_DB_NAME'

After Open Pass #2
session cursor cache count 21
session cursor cache hits 17

Before Pass #3
session cursor cache count 21
session cursor cache hits 18

1  SELECT    S.SID,    S.SERIAL# SERIALN  FROM    V$SESSION S,
2  SELECT    SN.NAME STAT_NAME,    M.VALUE  FROM    V$MYSTAT M,
3  SELECT    SQL_TEXT  FROM    V$OPEN_CURSOR  WHERE    SID=   
4  SELECT * FROM T4
5  SELECT * FROM T4
6  SELECT * FROM T4
7  SELECT * FROM T4
8  SELECT * FROM T4
9  SELECT * FROM T4
10  SELECT * FROM T4
11  SELECT * FROM T4
12  SELECT * FROM T4
13  SELECT * FROM T4
14  SELECT * FROM T4
15  SELECT * FROM T4
16  SELECT PARAMETER, VALUE FROM SYS.NLS_DATABASE_PARAMETERS WHE
17  insert into sys.aud$( sessionid,entryid,statement,ntimestamp
18  select /*+ connect_by_filtering */ privilege#,level from sys
19  select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_CONTEXT('U
20  select decode(failover_method, NULL, 0 , 'BASIC', 1, 'PRECON
21  select privilege# from sysauth$ where (grantee#=:1 or grante
22  select value$ from props$ where name = 'GLOBAL_DB_NAME'

After Open Pass #3
session cursor cache count 21
session cursor cache hits 32

Is that what you expected to see?

We still have one remaining question – is a larger shared pool required when increasing the SESSION_CACHED_CURSORS parameter (the parameter was set to the default value of 50 for this blog article).  To help you decide, refer to the following:

AskTom Article

Blog article written by Jonathan Lewis, specifically this comment:

“Every individiual holding a cursor open has an entry in x$kgllk – which is in the SGA – and these entries seem to be 172 bytes long in 10g (152 in 9i). So, clearly, if you hold more cursors open, you will be using more memory for these structures.”





V$SESSION’s ROW_WAIT_OBJ# Column Shows the DATA_OBJECT_ID – Verify the Documentation Challenge

7 06 2011

June 7, 2011

While reading through the alpha copy of a performance tuning book, I noticed a set of SQL statements that were identical to those found in the Oracle Database 11.2 Performance Tuning Guide.  The set of SQL statements from the Performance Tuning Guide follow:

10.3.1.1 Causes
To determine the possible causes, first query V$SESSION to identify the value of ROW_WAIT_OBJ# when the session waits for buffer busy waits. For example:

SELECT row_wait_obj#
  FROM V$SESSION
 WHERE EVENT = 'buffer busy waits';

To identify the object and object type contended for, query DBA_OBJECTS using the value for ROW_WAIT_OBJ# that is returned from V$SESSION. For example:

SELECT owner, object_name, subobject_name, object_type
  FROM DBA_OBJECTS
 WHERE data_object_id = &row_wait_obj;

In an earlier article we found that V$SESSION’s ROW_WAIT_OBJ# column indicated the OBJECT_ID, not the DATA_OBJECT_ID of the object (as found in DBA_OBJECTS) and the same was true for the obj# entry found in a 10046 trace file.  When you first create an index the OBJECT_ID and the DATA_OBJECT_ID values will be the same for the index, as displayed in DBA_OBJECTS.  However, when you rebuild the index the DATA_OBJECT_ID value for the index will change while the OBJECT_ID value remains unchanged.  Likewise, when you first create a table the OBJECT_ID and the DATA_OBJECT_ID values will be the same, as displayed in DBA_OBJECTS.  If you TRUNCATE a table, the OBJECT_ID value will remain the same while the DATA_OBJECT_ID value for the table will change.

The challenge is to build a test case that either confirms or refutes the claim made by the Oracle Database Performance Tuning Guide.  Possible references:

  • AskTom thread
  • Metalink (MOS) ID 15476.1 “FAQ about Detecting and Resolving Locking Conflicts”
  • Metalink (MOS) Doc ID 603661.1 “ORA-01410: Invalid Rowid When Using rowid Generated from V$Session and Dba_objects”
  • Another article found on this blog (take a look at the Other Resources links)







Follow

Get every new post delivered to your Inbox.

Join 144 other followers