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.
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
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).
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
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.
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 9026Hi 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
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
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
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):
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):
More information about ORADEBUG dumps is available on Julian Dyke’s website.