Open Cursor Leaks – Identifying the Problem

3 02 2010

February 3, 2010

Assume that one of the users receives an error message like this one from an application (caution: some errors may be bigger than they appear).

Just what does this error message mean?  It could mean that Oracle’s OPEN_CURSORS initialization parameter, which specifies the maximum number of cursors that may be open simultaneously by a single session, is set too low.  The error could also mean that a limit of the program, the database connection method, or the application development environment was hit.  Or, the error could potentially be a false alarm – maybe there was a completely different error (maybe out of memory) and this message just happened to be selected for presentation to the user.

First, let’s try a quick experiment:

(Session 1, Just After Connecting to the Database):

SELECT SID FROM V$MYSTAT WHERE ROWNUM<=1;

  SID
-----
  168

(Session 2):

SELECT
  SQL_ID,
  SUBSTR(SQL_TEXT,1,50) SQL_TEXT,
  COUNT(*) CNT
FROM
  V$OPEN_CURSOR
WHERE
  SID=168
GROUP BY
  SQL_ID,
  SUBSTR(SQL_TEXT,1,50)
ORDER BY
  SQL_ID;

SQL_ID        SQL_TEXT                                            CNT
------------- -------------------------------------------------- ----
1uzhrfn574t12 SELECT ATTRIBUTE,SCOPE,NUMERIC_VALUE,CHAR_VALUE,DA    1
2q93zsrvbdw48 select grantee#,privilege#,nvl(col#,0),max(mod(nvl    2
425wwycyjax6t DECLARE   SHOULD_EXECUTE INTEGER; BEGIN   SELECT D    1
53saa2zkr6wc3 select intcol#,nvl(pos#,0),col#,nvl(spare1,0) from    1
6769wyy3yf66f select pos#,intcol#,col#,spare1,bo#,spare2 from ic    1
6aq34nj2zb2n7 select col#, grantee#, privilege#,max(mod(nvl(opti    2
7ng34ruy5awxq select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.t    2
83taa7kaw59c1 select name,intcol#,segcol#,type#,length,nvl(preci    2
96g93hntrzjtr select /*+ rule */ bucket_cnt, row_cnt, cache_cnt,    1
a73wbv1yu8x5c select con#,type#,condlength,intcols,robj#,rcon#,m    2
bsa0wjtftg3uw select file# from file$ where ts#=:1                  1
c4pc3jhzjcmc7 SELECT CHAR_VALUE FROM SYSTEM.PRODUCT_PRIVS WHERE     1
d6vwqbw6r2ffk SELECT USER FROM DUAL                                 1
dyk4dprp70d74 SELECT DECODE('A','A','1','2') FROM DUAL              1
f8pavn1bvsj7t select con#,obj#,rcon#,enabled,nvl(defer,0) from c    2
g4y6nw3tts7cc BEGIN DBMS_APPLICATION_INFO.SET_MODULE(:1,NULL); E    1

16 rows selected.

(Session 1):

SELECT COUNT(*) FROM ALL_OBJECTS;

(Session 2 – Re-execute the same SQL statement):

...
16 rows selected.

No change in the number of open cursors.

(Session 1):

SELECT COUNT(*) FROM ALL_OBJECTS;

SELECT COUNT(*) FROM ALL_OBJECTS;

(Session 2 – Re-execute the same SQL statement):

SQL_ID        SQL_TEXT                                            CNT
------------- -------------------------------------------------- ----
1uzhrfn574t12 SELECT ATTRIBUTE,SCOPE,NUMERIC_VALUE,CHAR_VALUE,DA    1
2q93zsrvbdw48 select grantee#,privilege#,nvl(col#,0),max(mod(nvl    2
425wwycyjax6t DECLARE   SHOULD_EXECUTE INTEGER; BEGIN   SELECT D    1
53saa2zkr6wc3 select intcol#,nvl(pos#,0),col#,nvl(spare1,0) from    1
6769wyy3yf66f select pos#,intcol#,col#,spare1,bo#,spare2 from ic    1
6aq34nj2zb2n7 select col#, grantee#, privilege#,max(mod(nvl(opti    2
7ng34ruy5awxq select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.t    2
83taa7kaw59c1 select name,intcol#,segcol#,type#,length,nvl(preci    2
96g93hntrzjtr select /*+ rule */ bucket_cnt, row_cnt, cache_cnt,    1
a73wbv1yu8x5c select con#,type#,condlength,intcols,robj#,rcon#,m    2
bsa0wjtftg3uw select file# from file$ where ts#=:1                  1
c4pc3jhzjcmc7 SELECT CHAR_VALUE FROM SYSTEM.PRODUCT_PRIVS WHERE     1
d6vwqbw6r2ffk SELECT USER FROM DUAL                                 1
dr2v8xdg4w2ag SELECT COUNT(*) FROM ALL_OBJECTS                      1
dyk4dprp70d74 SELECT DECODE('A','A','1','2') FROM DUAL              1
f8pavn1bvsj7t select con#,obj#,rcon#,enabled,nvl(defer,0) from c    2
g4y6nw3tts7cc BEGIN DBMS_APPLICATION_INFO.SET_MODULE(:1,NULL); E    1

17 rows selected.

In the above, notice that the open cursor count increased and that the “SELECT COUNT(*) FROM ALL_OBJECTS” SQL statement with SQL_ID dr2v8xdg4w2ag is now listed in the V$OPEN_CURSOR output, indicating that it is now held open in the session cursor cache.  So, the SQL statements in the session cursor cache could be affecting the actual number of cursors that may remain open, as specified by the OPEN_CURSORS initialization parameter, so this could be a problem (I have not investigated to see what happens when the OPEN_CURSORS value is reached – whether or not Oracle will throw an error, or simply close one of the cached cursors).

Back to the error message, let’s spend a couple of minutes investigating this particular problem.  We execute a SQL statement that outputs the following (note that the HASH_VALUE is output, not the SQL_ID):

SID USER_NAME  PROGRAM     HASH_VALUE  SQL_TEXT                                                         CNT
--- ---------- ----------  ----------  ------------------------------------------------------------ -------
208 USER1      CUSINQ.EXE  1511368051  SELECT BITS FROM CUST_LINE_BINARY  where TYPE = :1       and      74
235 USER2      PLNWIN.EXE   881677082  select TRANSACTION_ID,    IT.TYPE, IT.CLASS, WORKORDER_TYPE,      15
237 USER3      PURENT.EXE   233497298  select ID from VENDOR where ACTIVE_FLAG = 'N'                     11
115 USER4      APIENT.EXE   233497298  select ID from VENDOR where ACTIVE_FLAG = 'N'                    228

Does the above show a problem?  Maybe, maybe not – it depends on what the SQL statement’s output is actually showing to us.  The above output is from a query of V$SESSION and V$OPEN_CURSOR.  SID 115 (USER4) had 228 open cursors for the SQL statement “select ID from VENDOR where ACTIVE_FLAG = ‘N’“, and SID 237 (USER3) had 11 cursors open for the same SQL statement – is this a problem?  Maybe, maybe not.  At the point that this output was captured, the APIENT.EXE program was active for only a short period of time, but just a couple of minutes after the above was captured, the application crashed with the error message shown in the picture at the top of this article.  Was it a problem with too small of a value for the OPEN_CURSORS parameter?

SQL> SHOW PARAMETER OPEN_CURSORS

NAME            TYPE        VALUE
--------------- ----------- -----
open_cursors    integer     1000

From the above, probably not.  Some development environments limit the number of simulatneously open cursors in an application (or worse yet limit the sum of all cursors opened in all applications developed with that development environment that are concurrently running on a computer) to a number that is substantially lower than the 1,000 cursors permitted by the OPEN_CURSORS parameter.  This particular program was apparently developed using a version of the Centura/Gupta/Unify SQLWindows development environment that limits each application to no more than 300 open cursors.  In reality, 300 is a high limit – so hitting that limit should be uncommon, yet the application has 228 cursors open for this one SQL statement.  It appears that this application has a cursor leak, where a cursor is opened, but never closed (until the application is closed or the program crashes).  So, a quick examination of a 10046 trace for the session which was enabled in a logon trigger finds this:

PARSING IN CURSOR #4 len=69 dep=2 uid=0 oct=42 lid=0 tim=1182428884 hv=1576194328 ad='77846918'
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12'
...
PARSING IN CURSOR #4 len=45 dep=0 uid=50 oct=3 lid=50 tim=3416927811 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #8 len=45 dep=0 uid=50 oct=3 lid=50 tim=3620531267 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #9 len=45 dep=0 uid=50 oct=3 lid=50 tim=3724573181 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #26 len=45 dep=0 uid=50 oct=3 lid=50 tim=3827005408 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #30 len=45 dep=0 uid=50 oct=3 lid=50 tim=3848476712 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #19 len=45 dep=0 uid=50 oct=3 lid=50 tim=3995284712 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #20 len=45 dep=0 uid=50 oct=3 lid=50 tim=4088861749 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
...

PARSING IN CURSOR #254 len=45 dep=0 uid=50 oct=3 lid=50 tim=3223320608 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #78 len=45 dep=0 uid=50 oct=3 lid=50 tim=3336508540 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #260 len=45 dep=0 uid=50 oct=3 lid=50 tim=3336615021 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
PARSING IN CURSOR #251 len=45 dep=0 uid=50 oct=3 lid=50 tim=3356820371 hv=233497298 ad='88d08b70'
select ID from VENDOR where ACTIVE_FLAG = 'N'
...
WAIT #259: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3357352080
WAIT #259: nam='SQL*Net message from client' ela= 279 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3357352383
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3357352417
*** 2008-08-12 15:52:59.826
WAIT #0: nam='SQL*Net message from client' ela= 157430298 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514782745
XCTEND rlbk=1, rd_only=0
WAIT #0: nam='db file sequential read' ela= 10308 file#=4 block#=221289 blocks=1 obj#=12464 tim=3514793577
WAIT #0: nam='log file sync' ela= 105 buffer#=16352 p2=0 p3=0 obj#=12464 tim=3514794105
WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514794195
WAIT #0: nam='SQL*Net message from client' ela= 3539 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514797765
STAT #7 id=1 cnt=1 pid=0 pos=1 obj=11900 op='TABLE ACCESS FULL ACCOUNT_PERIOD (cr=8 pr=0 pw=0 time=83 us)'
XCTEND rlbk=1, rd_only=1
...
XCTEND rlbk=1, rd_only=1
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514806922
WAIT #0: nam='SQL*Net message from client' ela= 263 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514807200
STAT #4 id=1 cnt=0 pid=0 pos=1 obj=12943 op='TABLE ACCESS FULL VENDOR (cr=122 pr=0 pw=0 time=2238 us)'
XCTEND rlbk=1, rd_only=1
...
XCTEND rlbk=1, rd_only=1
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514807792
WAIT #0: nam='SQL*Net message from client' ela= 265 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514808072
STAT #9 id=1 cnt=0 pid=0 pos=1 obj=12943 op='TABLE ACCESS FULL VENDOR (cr=122 pr=0 pw=0 time=2235 us)'
XCTEND rlbk=1, rd_only=1
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514808212
WAIT #0: nam='SQL*Net message from client' ela= 249 driver id=1413697536 #bytes=1 p3=0 obj#=12464 tim=3514808477

STAT #8 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE  SEMAPHORE (cr=1 pr=0 pw=0 time=99 us)'
STAT #8 id=2 cnt=1 pid=1 pos=1 obj=12738 op='INDEX UNIQUE SCAN X_SEMAPHORE_0 (cr=1 pr=0 pw=0 time=14 us)'
XCTEND rlbk=1, rd_only=1
...

Once a cursor is closed, Oracle will re-use the CURSOR # associated with that cursor when the next SQL statement is executed (assuming that the SQL statement is not already held open in the session cursor cache).  If the PARSING IN CURSOR # value keeps increasing, that is a sign that cursors are not being closed either due to the design of application code (it might be intentional to reduce the number of soft parses) or the session cursor cache.  From the above, it looks like the application crashed at 2008-08-12 15:52:59.826 and a rollback (XCTEND rlbk=1, rd_only=0) was performed that affected previously changed, but not committed data.  Once the program crashed, Oracle wrote the STAT lines for all cursors that were still open.  In the above, we see the STAT lines that for cursor #4 and #9 were written after the crash, and those cursors were opened fairly early in the trace activity (note that the 32 bit value used for the tim= entry wrapped around 0 while tracing was enabled).  The STAT line output for cursor #8 after the crash shows a different execution plan than that for cursor #9, indicating that at some point the “select ID from VENDOR where ACTIVE_FLAG = ‘N’” SQL statement that was opened early in the trace file for cursor #8 successfully closed at some point before the crash.  In this case, the 10046 trace file provided significant evidence that a programming fix was required.  The developers to the rescue…  :-)

Let’s try executing the following SQL statement in a time period unrelated to the above exploration (with SQL statements executed by some users explicitly omitted and some SQL statements explicitly omitted – warning, you probably should not repeatedly execute this SQL statement due to the potential for latching problems):

SELECT
  OC.SID,
  OC.USER_NAME,
  S.PROGRAM,
  COUNT(*) COUNTER,
  OC.SQL_ID,
  OC.SQL_TEXT
FROM
  V$OPEN_CURSOR OC,
  V$SESSION S
WHERE
  OC.SQL_TEXT NOT LIKE '%obj#,%'
  AND OC.SQL_TEXT NOT LIKE '%grantee#,%'
  AND OC.SQL_TEXT NOT LIKE '%privilege#%'
  AND OC.SQL_TEXT NOT LIKE 'DECLARE%'
  AND OC.SQL_TEXT NOT LIKE '%/*+ rule */%'
  AND OC.SQL_TEXT NOT LIKE '%col#%'
  AND OC.SQL_TEXT NOT LIKE '%sys.mon_mods$%'
  AND OC.SQL_TEXT NOT LIKE '%obj#=%'
  AND OC.SQL_TEXT NOT LIKE '%update$,%'
  AND OC.SID=S.SID
  AND OC.USER_NAME NOT IN ('SYS','DBSNMP','SYSTEM','SYSMAN','RMAN')
GROUP BY
  OC.SID,
  OC.USER_NAME,
  S.PROGRAM,
  OC.SQL_ID,
  OC.SQL_TEXT
HAVING
  COUNT(*)>=10
ORDER BY
  OC.USER_NAME,
  OC.SID,
  OC.SQL_TEXT;

  SID USER_NAME PROGRAM                    COUNTER SQL_ID         SQL_TEXT                                                   
----- --------- -------------------------- ------- -------------  ------------------------------------------------------------
  208 USER1     PLNWIN.EXE                      20 5ngzsfstg8tmy  select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,
  173 USER2     NCMR.exe                        10 5ngzsfstg8tmy  select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,
  173 USER2     NCMR.exe                        10 cqgv56fmuj63x  select owner#,name,namespace,remoteowner,linkname,p_timestam
  302 USER3     CapturePhoneData.exe            11 36405ka00hcv5  INSERT INTO PHONE_LOG (    ACCESS_DATE,    EXTENSION       
  230 USER4     bclabr.exe                      10 6qrbg23ub5syp  SELECT calc_end_qty, completed_qty  FROM OPERATION  WHERE WO
  235 USER5     bclabr.exe                      10 6qrbg23ub5syp  SELECT calc_end_qty, completed_qty  FROM OPERATION  WHERE WO
  246 USER6     PURENT.EXE                      14 5ngzsfstg8tmy  select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,
  171 USER7     CorrectiveActionReport.exe      15 5ngzsfstg8tmy  select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,
  167 USER8     NetworkTest.exe                 53 3ubfyvhz2zdfk  SELECT HOST_NAME , LAST_DEAD_PING , WARNING_MINUTES , IP_ADD
  167 USER8     NetworkTest.exe                 55 55gk2gdxb9mvc  SELECT IP , COMPUTER_NAME  FROM CUSTAPP.WEB_LOCAL_IP_LOOKUP
  167 USER8     NetworkTest.exe                 88 4xu4rvudbc83p  UPDATE   DOC_OBJECT_DESCRIPTION   SET   LAST_GOOD_PI       
  296 USER9     ReceivePO.exe                   10 fr464ph8jb4zm  SELECT   COUNT(*) LINES  FROM   CUSTAPP.PURC_ORDER_OPEN  WHE
  296 USER9     ReceivePO.exe                   12 5ft6wg3qhvw58  SELECT   RCE.PURC_ORDER_ID,   RCE.PURC_ORDER_LINE_NO,   P.PR
...

USER1 has about 20 cursors open for SQL_ID 5ngzsfstg8tmy, which appears to be an internal SQL statement that is executed on behalf of the session.  The same SQL_ID appears for a couple of other sessions.  Let’s take a look at that SQL statement a little more closely.

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('5ngzsfstg8tmy',NULL,'TYPICAL'));

SQL_ID  5ngzsfstg8tmy, child number 0        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 1        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 2        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 3        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 4        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 5        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 7        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 9        
-------------------------------------        
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 10       
--------------------------------------       
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 11       
--------------------------------------       
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

-

SQL_ID  5ngzsfstg8tmy, child number 12       
--------------------------------------       
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.     
dataobj#,o.flags from obj$ o where o.obj#=:1 

Plan hash value: 3317232865                  

----------------------------------------------
| Id  | Operation                   | Name   |
----------------------------------------------
|   0 | SELECT STATEMENT            |        |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |
----------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)                 

Note                  
-----                 
   - rule based optimizer used (consider using cbo)

-

SQL_ID  5ngzsfstg8tmy, child number 14       
--------------------------------------       
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataob
j#,o.flags from obj$ o where o.obj#=:1       

Plan hash value: 3317232865                  

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |       |       |     2 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| OBJ$   |     1 |    74 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | I_OBJ1 |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("O"."OBJ#"=:1)

There are 12 child cursors for this SQL statement still in the library cache, or at least the execution plans are still available.  If we check V$SQL_SHARED_CURSOR we might be able to tell why at least 15 child cursors were created for this one SQL statement:

SQL_ID        ADDRESS          CHILD_ADDRESS    CN USOOSLSEBPISTABDLTRIIRLIOSMUTNFAITDLDBPCSRPTMBMROPMFL
------------- ---------------- ---------------- -- -----------------------------------------------------
5ngzsfstg8tmy 000000018D960FF0 000000018D9600C0  0 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 000000018D642EA8  1 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN
              000000018D960FF0 000000018A2D1B98  2 NNYNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 0000000180B86C60  3 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 000000016AC7CD28  4 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 0000000161B54780  5 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 0000000175FE5788  6 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 0000000178648270  7 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 0000000173425140  9 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 000000017322B9C0 10 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 00000001834D71D8 11 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 00000001767FE0C8 12 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN
              000000018D960FF0 000000017D28DFA0 14 NNYNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNYYNNNN

In the above, the first O is OPTIMIZER_MISMATCH, the second S is STATS_ROW_MISMATCH, the last R is ROLL_INVALID_MISMATCH, and the last O is OPTIMIZER_MODE_MISMATCH.  A lot of the child cursors were created due to statistics collection – I wonder if some of these older child cursors are still open by sessions.  Oracle Database 10.2.0.x does not offer the IS_SHAREABLE column in V$SQL, but the IS_OBSOLETE column shows that none of the 13 child cursors still in the library cache has been marked as obsolete:

SELECT
  CHILD_NUMBER CN,
  PARSING_SCHEMA_NAME,
  OPTIMIZER_ENV_HASH_VALUE OPTIMIZER_ENV,
  INVALIDATIONS,
  PARSE_CALLS,
  IS_OBSOLETE,
  FIRST_LOAD_TIME,
  TO_CHAR(LAST_ACTIVE_TIME,'YYYY-MM-DD/HH24:MI:SS') LAST_ACTIVE_TIME
FROM
  V$SQL
WHERE
  SQL_ID='5ngzsfstg8tmy';

CN PARSING_SC OPTIMIZER_ENV INVALIDATIONS PARSE_CALLS I FIRST_LOAD_TIME     LAST_ACTIVE_TIME  
-- ---------- ------------- ------------- ----------- - ------------------- -------------------
 0 SYS           1515106640             1        3107 N 2009-11-27/16:40:02 2010-01-25/14:53:12
 1 SYS           1515106640             0         240 N 2009-11-27/16:40:02 2010-01-25/22:03:15
 2 SYS           2540482053             0        1073 N 2009-11-27/16:40:02 2010-02-01/08:01:01
 3 SYS           1515106640             0        2810 N 2009-11-27/16:40:02 2010-02-01/03:40:02
 4 SYS           1515106640             0         583 N 2009-11-27/16:40:02 2010-01-25/18:09:13
 5 SYS           1515106640             0         239 N 2009-11-27/16:40:02 2010-02-01/10:19:44
 6 SYS           2540482053             0          69 N 2009-11-27/16:40:02 2010-02-01/10:14:58
 7 SYS           1515106640             0         763 N 2009-11-27/16:40:02 2010-01-25/10:49:16
 9 SYS           1515106640             0         510 N 2009-11-27/16:40:02 2010-02-01/08:16:10
10 SYS           2540482053             0         163 N 2009-11-27/16:40:02 2010-02-01/06:54:04
11 SYS           1515106640             0         260 N 2009-11-27/16:40:02 2010-01-31/23:07:26
12 SYS           2230081206             0           8 N 2009-11-27/16:40:02 2010-02-01/03:48:43
14 SYS           1515106640             0         654 N 2009-11-27/16:40:02 2010-02-01/06:10:55

The OPTIMIZER_ENV_HASH_VALUE is different for some of the child cursors, although all of the SQL statements were parsed by the SYS user.  Let’s take a look at what is different about the optimizer environment for some of the SQL statements:

SELECT
  CHILD_NUMBER CN,
  NAME,
  VALUE,
  ISDEFAULT DEF
FROM
  V$SQL_OPTIMIZER_ENV
WHERE
  SQL_ID='5ngzsfstg8tmy'
  AND CHILD_NUMBER in (0,2,12)
ORDER BY
  NAME,
  CHILD_NUMBER;

If we just list the differences in the output for the three child cursors, we see the following:

 CN NAME                        VALUE           DEF
--- --------------------------- --------------- ---
  2 _optim_peek_user_binds      false           NO
  0 optimizer_mode              choose          NO
  2 optimizer_mode              choose          NO
 12 optimizer_mode              rule            NO

Interesting, two of the child cursors are using an OPTIMIZER_MODE of CHOOSE, and one is using an OPTIMIZER_MODE of RULE, neither of which are valid (supported) OPTIMIZER_MODE values for this release of Oracle Database.  Of course, it is possible to supply a hint to force the use of the RULE optimizer (might be used by Oracle’s internal SQL statements), but CHOOSE?  Just to verify:

SQL> SHOW PARAMETER OPTIMIZER_MODE

NAME             TYPE        VALUE
---------------- ----------- --------
optimizer_mode   string      ALL_ROWS

The _OPTIM_PEEK_USER_BINDS is disabled for one of the three unique OPTIMIZER_ENV_HASH_VALUE values, which was implemented in a logon trigger to “fix” problems with certain applications that either fail to initialize bind variable values on the initial hard parse, or select unpopular values during the initial hard parse.  But, there is no logon trigger that sets the OPTIMIZER_MODE to CHOOSE for a session.

OK, the topic is drifting a bit.  USER1 (SID 208) has 20 cursors open with this internal SQL statement.  I wonder if the number of child cursors in the library cache could be a possible cause, combined with the value of 200 for SESSION_CACHED_CURSORS (if a SQL statement is executed at least 3 times, it will be added to the cached cursors for the session and held open, even when the client explicitly closes the cursor)?

I suppose at this point, I should probably try to determine why the NetworkTest.exe program has 88 open cursors for an update statement, 55  open cursors for one select statement, and 53 open cursors for a second select statement…  To crash, or not to crash, is not the question – it is only a matter of time.








Follow

Get every new post delivered to your Inbox.

Join 141 other followers