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.


Actions

Information

9 responses

4 02 2010
Anand Prakash

Hi Charles,

How to find why the cursor is still open for a session.I have a session with a logon date on 29-JAN-2010, which is INACTIVE and has 1 open_cursor.This session is having the maximum cpu usage,though inactive.How do i go ahead for analyzing it.

Regards,
Anand

4 02 2010
Charles Hooper

Anand,
It is important to determine if the session is still consuming CPU time – you will probably need to monitor the change in the DB CPU value in V$SESS_TIME_MODEL (assuming that you are running at least Oracle 10.1) for the session to determine if the session is still consuming CPU time. The DB CPU value should not increase for the session if the session is INACTIVE – see the script and example in this blog article:
http://hoopercharles.wordpress.com/2010/01/14/working-with-oracles-time-model-data-2/

You might also considering monitoring the DB time value in the same performance view to see if the session is currently stuck in a wait event, rather than consuming CPU time (in that view, DB time – DB CPU = wait event time for a single session).

17 02 2010
Anand

Hi Charles,
I am having a issue of OS memory crunch.The sever has 16Gb RAM, and hosts 2 db.The total sag+pga combined is ~10.5GB.For one of the database, i see in TOP command, RES column values like 1100M,1245M , though these sessions are inactive and the logon_time is of 9th Feb.The sessions are also having open_cursor.Can this is a bottleneck?Can snipping these sessions be useful?

Anand

17 02 2010
Charles Hooper

Anand,

I believe that there is potential for double counting of shared memory segments. I suggest taking a look at the following:
Excellent Video and Documentation about Oracle Memory Usage
asktom.oracle.com Article about Oracle Memory Usage
Oracle Documentation Link about OS Tools

Regarding the query of V$OPEN_CURSOR, yes – open cursors will consume the server’s memory. I suggest also grouping on the SQL_ID so that you are able to determine if it is the same SQL statement that is open more than 600 times (opened and then abandoned), or if those 600+ entries in the count are 600+ different SQL statements caused by too large of a value for the SESSION_CACHED_CURSORS parameter.

17 02 2010
Anand

For reference :-

select oc.sid, count(*) ,s.status,to_char(s.logon_time,'DD-MM-YY HH24:MI:SS')in_time,s.LAST_CALL_ET from v$open_cursor oc,
v$session s  where oc.sid=s.sid and oc.user_name='APPLICATION_SCHEMA' group by oc.sid,s.status,s.logon_time,s.LAST_CALL_ET;

Session
     ID   COUNT(*) STATUS   IN_TIME           LAST_CALL_ET
------- ---------- -------- ----------------- ------------
    235        715 INACTIVE 12-02-10 09:50:19            3
    222        662 INACTIVE 09-02-10 22:53:44          673
    260        672 INACTIVE 09-02-10 16:51:18       417235
    225        672 INACTIVE 09-02-10 22:53:44            0
    248        657 INACTIVE 09-02-10 17:02:36       445957
    237        645 INACTIVE 09-02-10 16:51:38       417235
    219        666 INACTIVE 09-02-10 22:53:44         9026
    234        678 INACTIVE 12-02-10 09:50:19         9026
    232        674 INACTIVE 09-02-10 16:50:25         9026
    230        661 INACTIVE 09-02-10 22:53:44          673
    227        677 INACTIVE 09-02-10 22:53:44           14
    243        648 INACTIVE 09-02-10 17:02:36       445957
    224        780 INACTIVE 11-02-10 21:10:00        11091
    231        667 INACTIVE 09-02-10 16:51:38         9026
17 02 2010
Anand

Hi Charles,
Thanks for the input.Will check and definitely let you know.One more question , the server’s memory allocated to the open cursor’s session will be outside the SGA/PGA.It will be something that the PID is curently holding in the RAM.Am i right?

Anand

17 02 2010
Charles Hooper

It is my understanding that the memory usage will be accumulated as PGA memory usage if you have a dedicated server configuration. I found a couple of message threads on asktom.oracle.com that will probably explain to you the memory usage much better than I could:
http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:4269591917792

http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:580621300346132183

http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:865497961356

17 02 2010
Anand

Hi Charles,
I am having a solaris box.In TOP(unix), i am getting RES (Resident Size) as 1124M ,1170M..etc for PIDs.When i check for the sessions belonging to PIDs they are for the application sessions which are INACTIVE but connected.How do i confirm that the these sessions are holding server’s memory and the reason for the same?

Regards,
Anand

18 02 2010
Charles Hooper

Anand,

I will try to answer your question – if anyone else reading this blog has a better suggestion, please offer that suggestion.

You could just query V$SESSTAT, something like this (see the documentation):

SELECT
  S.USERNAME,
  S.PROGRAM,
  S.STATUS,
  SS.SID,
  SN.NAME,
  SS.VALUE
FROM
  V$STATNAME SN,
  V$SESSTAT SS,
  V$SESSION S
WHERE
  SS.STATISTIC#=SN.STATISTIC#
  AND SN.NAME='session pga memory'
  AND SS.SID=S.SID
ORDER BY
  SS.VALUE DESC,
  SS.SID;

If you are running Oracle 10.2.0.1 or higher, you could query V$PROCESS_MEMORY, something like this:

SELECT
  P.PID,
  P.SPID,
  P.PROGRAM,
  S.PROGRAM,
  S.USERNAME,
  S.SID,
  P.PGA_USED_MEM,
  P.PGA_ALLOC_MEM,
  P.PGA_FREEABLE_MEM,
  P.PGA_MAX_MEM,
  PM.SQL_ALLOCATED,
  PM.SQL_USED,
  PM.SQL_MAX_ALLOCATED,
  PM.PLSQL_ALLOCATED,
  PM.PLSQL_USED,
  PM.PLSQL_MAX_ALLOCATED,
  PM.OLAP_ALLOCATED,
  PM.OLAP_USED,
  PM.OLAP_MAX_ALLOCATED,
  PM.JAVA_ALLOCATED,
  PM.JAVA_USED,
  PM.JAVA_MAX_ALLOCATED,
  PM.OTHER_ALLOCATED,
  PM.OTHER_USED,
  PM.OTHER_MAX_ALLOCATED,
  PM.FREEABLE_ALLOCATED
FROM
  V$PROCESS P,
  V$SESSION S,
  (SELECT
    PID,
    SERIAL#,
    MAX(DECODE(CATEGORY,'SQL',ALLOCATED,0)) SQL_ALLOCATED,
    MAX(DECODE(CATEGORY,'SQL',USED,0)) SQL_USED,
    MAX(DECODE(CATEGORY,'SQL',MAX_ALLOCATED,0)) SQL_MAX_ALLOCATED,
    MAX(DECODE(CATEGORY,'PL/SQL',ALLOCATED,0)) PLSQL_ALLOCATED,
    MAX(DECODE(CATEGORY,'PL/SQL',USED,0)) PLSQL_USED,
    MAX(DECODE(CATEGORY,'PL/SQL',MAX_ALLOCATED,0)) PLSQL_MAX_ALLOCATED,
    MAX(DECODE(CATEGORY,'OLAP',ALLOCATED,0)) OLAP_ALLOCATED,
    MAX(DECODE(CATEGORY,'OLAP',USED,0)) OLAP_USED,
    MAX(DECODE(CATEGORY,'OLAP',MAX_ALLOCATED,0)) OLAP_MAX_ALLOCATED,
    MAX(DECODE(CATEGORY,'JAVA',ALLOCATED,0)) JAVA_ALLOCATED,
    MAX(DECODE(CATEGORY,'JAVA',USED,0)) JAVA_USED,
    MAX(DECODE(CATEGORY,'JAVA',MAX_ALLOCATED,0)) JAVA_MAX_ALLOCATED,
    MAX(DECODE(CATEGORY,'Other',ALLOCATED,0)) OTHER_ALLOCATED,
    MAX(DECODE(CATEGORY,'Other',USED,0)) OTHER_USED,
    MAX(DECODE(CATEGORY,'Other',MAX_ALLOCATED,0)) OTHER_MAX_ALLOCATED,
    MAX(DECODE(CATEGORY,'Freeable',ALLOCATED,0)) FREEABLE_ALLOCATED
  FROM
    V$PROCESS_MEMORY
  GROUP BY
    PID,
    SERIAL#) PM
WHERE
  P.ADDR=S.PADDR(+)
  AND P.PID=PM.PID
  AND P.SERIAL#=PM.SERIAL#
ORDER BY
  PGA_ALLOC_MEM DESC;

The above showed that I have an inactive session that has 10,915,985 bytes of memory allocated, with 2,264,137 bytes that are in use, 720,896 bytes are freeable, and the maximum amount of memory used by the session was 53,776,529 bytes. The “Other” allocated is currently at 9,994,145 bytes (of the 10,915,985 bytes).

If the above information was not enough for me, I could turn to page 268 in the Expert Oracle Practices book (chapter 8 written by Randolf Geist and myself) and dump the PGA and UGA memory contents to a trace file, like this (in SQL*Plus, connected as SYS, 34 is the PID of the session that is inactive):

ORADEBUG SETORAPID 34
ORADEBUG UNLIMIT
ORADEBUG DUMP HEAPDUMP 5
ORADEBUG CLOSE_TRACE

More information about ORADEBUG dumps is available on Julian Dyke’s website.

Leave a Reply

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

WordPress.com Logo

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

Twitter picture

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

Facebook photo

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

Google+ photo

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

Connecting to %s




Follow

Get every new post delivered to your Inbox.

Join 139 other followers

%d bloggers like this: