open cursor exceeded
A reader, May 19, 2011 - 5:23 am UTC
Hi tom
Thanks for pointing out to check the duplicate in open_cursor. Following are question regarding some of duplication occurring
a) One procedure is getting input parameter and returning number as out put parameter. In procedure the input parameter is directly using then why it is showing multiple time. Our understanding is that if in procedure we are using parameter then it is bind.
b) Following query is used in multiple triggers and is showing multiple time should not it be shown once SELECT SYS_CONTEXT('USERENV','HOST'),SYS_CONTEXT('USERENV','OS_USER'),
SYS_CONTEXT('USERENV','SESSION_USER'),SYS_CONTEXT('USERENV','IP_ADDRESS')
INTO V_HOST, V_OS_USER ,V_SESSION_USER, V_IP_ADDRESS FROM DUAL;
c) In trigger following is used and it is also appearing multiple times.
INSERT INTO Temp_A
(pk_id, desc, HOST,OS_USER,SESSION_USER,IP_ADDRESS,LOGGED_DATE,DML_STATEMENT )VALUES (SEQ_LOG_id.NEXTVAL, :N.desc,V_HOST,V_OS_USER,V_SESSION_USER,V_IP_ADDRESS,SYSTIMESTAMP,'INSERT');
Thanks
May 19, 2011 - 8:40 am UTC
a) you get a duplicate if you explicitly open a cursor with a given sql text AND THEN open another cursor with that same text and so on.
give me an example to work with here. By "procedure" do you mean plsql? show me some sample code
b) each trigger would have its own cursor handle, that is ok here. plsql caches cursors PERFECTLY, if you are using static sql in plsql - you can ignore those in v$open_cursor. Look for your applications sql.
the cursors plsql holds open will be closed if you run out of slots - they are not the problem. Look for your APPLICATION sql, that will be the problem - look for sql that is NOT static sql in plsql.
Hibernate / C3P0 / Oracle 10G / Cursor Madness
brian, July 21, 2011 - 3:19 pm UTC
Hello friends -
(Did I double post somehow? Sorry!)
Hibernate 3.2 / C3P0 0.9 connecting to an Oracle 10g database.
I'm doing everyhing I know how to do in order to close my cursors out at an application level, and I keep on seeing the Max Cursors exceeded errors. I went ahead and set Hibernate logging to debug, a small portion of which I am attaching below. It sure tells me that it is closing my prepared statemetns and result sets.
Curiously, if you scan the log file you can see that the build up of cursors is gradual, and does sometimes decrease over time, just more of a two steps forward, one step back pattern; i.e.,
****************************************************
15:47:56,008 DEBUG AbstractBatcher:410 - about to open PreparedStatement (open PreparedStatements: 3, globally: 3)
15:47:56,008 DEBUG SQL:111 - select tinstantal0_.ACCT_ID as col_0_0_, tinstantal0_.PER_ID as col_0_1_, tinstantal0_.PREM_ID as col_0_2_, tinstantal0_.SP_ID as col_0_3_, tinstantal0_.SP_TYPE_CD as col_0_4_, tinstantal0_.ENTITY_NAME as col_0_5_, tinstantal0_.EMAILID as col_0_6_, tinstantal0_.PHONE as col_0_7_, tinstantal0_.PHONE_TYPE as col_0_8_, tinstantal0_.OD_OPTION_SW as col_0_9_, tinstantal0_.ODE_OPTION_SW as col_0_10_, tinstantal0_.ADDRESS1 as col_0_11_ from InstantAlert.T_INSTANT_ALERT_LOOKUP_VW tinstantal0_ where phone=?
15:47:56,040 DEBUG AbstractBatcher:426 - about to open ResultSet (open ResultSets: 3, globally: 3)
15:47:56,040 DEBUG IteratorImpl:113 - attempting to retrieve next results
15:47:56,040 DEBUG IteratorImpl:120 - retrieved next results
15:47:56,040 DEBUG IteratorImpl:133 - assembling results
15:47:56,040 DEBUG IteratorImpl:113 - attempting to retrieve next results
15:47:56,040 DEBUG IteratorImpl:120 - retrieved next results
15:47:56,040 DEBUG IteratorImpl:152 - returning current results
15:47:56,040 DEBUG IteratorImpl:133 - assembling results
15:47:56,040 DEBUG IteratorImpl:113 - attempting to retrieve next results
15:47:56,040 DEBUG IteratorImpl:120 - retrieved next results
15:47:56,040 DEBUG IteratorImpl:152 - returning current results
15:47:56,040 DEBUG IteratorImpl:133 - assembling results
15:47:56,040 DEBUG IteratorImpl:113 - attempting to retrieve next results
15:47:56,040 DEBUG IteratorImpl:120 - retrieved next results
15:47:56,040 DEBUG IteratorImpl:152 - returning current results
15:47:56,040 DEBUG IteratorImpl:133 - assembling results
15:47:56,040 DEBUG IteratorImpl:113 - attempting to retrieve next results
15:47:56,040 DEBUG IteratorImpl:120 - retrieved next results
15:47:56,040 DEBUG IteratorImpl:152 - returning current results
15:47:56,040 DEBUG IteratorImpl:133 - assembling results
15:47:56,040 DEBUG IteratorImpl:113 - attempting to retrieve next results
15:47:56,040 DEBUG IteratorImpl:120 - retrieved next results
15:47:56,040 DEBUG IteratorImpl:152 - returning current results
15:47:56,040 DEBUG IteratorImpl:133 - assembling results
15:47:56,040 DEBUG IteratorImpl:113 - attempting to retrieve next results
15:47:56,040 DEBUG IteratorImpl:116 - exhausted results
15:47:56,040 DEBUG IteratorImpl:86 - closing iterator
15:47:56,040 DEBUG AbstractBatcher:433 - about to close ResultSet (open ResultSets: 4, globally: 4)
15:47:56,040 DEBUG AbstractBatcher:418 - about to close PreparedStatement (open PreparedStatements: 4, globally: 4)
******************************************************
Followed shortly there after:
******************************************************
15:47:56,118 DEBUG AbstractBatcher:410 - about to open PreparedStatement (open PreparedStatements: 3, globally: 3)
15:47:56,118 DEBUG SQL:111 - select tinstantal0_.ACCT_ID as ACCT1_20_, tinstantal0_.PER_ID as PER2_20_, tinstantal0_.PREM_ID as PREM3_20_, tinstantal0_.SP_ID as SP4_20_, tinstantal0_.SP_TYPE_CD as SP5_20_, tinstantal0_.ENTITY_NAME as ENTITY6_20_, tinstantal0_.EMAILID as EMAILID20_, tinstantal0_.PHONE as PHONE20_, tinstantal0_.PHONE_TYPE as PHONE9_20_, tinstantal0_.OD_OPTION_SW as OD10_20_, tinstantal0_.ODE_OPTION_SW as ODE11_20_, tinstantal0_.ADDRESS1 as ADDRESS12_20_ from InstantAlert.T_INSTANT_ALERT_LOOKUP_VW tinstantal0_ where sp_id=? and (phone_type=? or phone_type=? or phone_type=?) order by length(phone_type)
15:47:56,133 DEBUG AbstractBatcher:426 - about to open ResultSet (open ResultSets: 3, globally: 3)
15:47:56,133 DEBUG Loader:1197 - result row: EntityKey[us.fl.ci.tlh.uu.notification.data.cis.TInstantAlertLookup#component[acctId,perId,premId,spId,spTypeCd,entityName,emailid,phone,phoneType,odOptionSw,odeOptionSw,address1]{spTypeCd=E-GS-ND, phone= 422-1009, odOptionSw=N, premId=0844034610, odeOptionSw=N, phoneType=OLD PHONE1, acctId=6137085610, perId=1278743610, address1=623 Arbor Station Ln, spId=0844034454, emailid= , entityName=Arbor Station Apts}]
15:47:56,149 DEBUG AbstractBatcher:433 - about to close ResultSet (open ResultSets: 4, globally: 4)
15:47:56,149 DEBUG AbstractBatcher:418 - about to close PreparedStatement (open PreparedStatements: 4, globally: 4)
15:47:56,149 DEBUG TwoPhaseLoad:130 - resolving associations for [us.fl.ci.tlh.uu.not}]
15:47:56,149 DEBUG TwoPhaseLoad:226 - done materializing entity [u]
15:47:56,149 DEBUG StatefulPersistenceContext:860 - initializing non-lazy collections
15:47:56,149 INFO TInstantAlertLookupDAO:219 - Iterating through list of numbers
15:47:56,149 INFO TInstantAlertLookupDAO:333 - about to parse out customer names
15:47:56,149 DEBUG AbstractFlushingEventListener:134 - processing flush-time cascades
15:47:56,149 DEBUG AbstractFlushingEventListener:177 - dirty checking collections
15:47:56,149 DEBUG AbstractFlushingEventListener:108 - Flushed: 0 insertions, 0 updates, 0 deletions to 44 objects
15:47:56,149 DEBUG AbstractFlushingEventListener:114 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
15:47:56,149 DEBUG Printer:106 - listing entities:
15:47:56,149 DEBUG Printer:113 - us.fl.ci.tlh.uu.notification.data.cis.TInstantAlertLookup{ LINES REMOVED TO SCRUB OUT SENSITIVE INOFORMATION.}
15:47:56,165 DEBUG Printer:110 - more......
15:47:56,165 DEBUG AbstractBatcher:410 - about to open PreparedStatement (open PreparedStatements: 3, globally: 3)
15:47:56,165 DEBUG SQL:111 - select tinstantal0_.ACCT_ID as col_0_0_, tinstantal0_.PER_ID as col_0_1_, tinstantal0_.PREM_ID as col_0_2_, tinstantal0_.SP_ID as col_0_3_, tinstantal0_.SP_TYPE_CD as col_0_4_, tinstantal0_.ENTITY_NAME as col_0_5_, tinstantal0_.EMAILID as col_0_6_, tinstantal0_.PHONE as col_0_7_, tinstantal0_.PHONE_TYPE as col_0_8_, tinstantal0_.OD_OPTION_SW as col_0_9_, tinstantal0_.ODE_OPTION_SW as col_0_10_, tinstantal0_.ADDRESS1 as col_0_11_ from InstantAlert.T_INSTANT_ALERT_LOOKUP_VW tinstantal0_ where phone=?
15:47:56,180 DEBUG AbstractBatcher:426 - about to open ResultSet (open ResultSets: 3, globally: 3) -- SEE THINGS ARE SORT OF GETTING CLOSED OFF AS EXPECTED SOMETIMES!
********************************************************
Eventually, however, I reach my breaking point; i.e.,
*******************************************************
15:52:11,430 DEBUG AbstractBatcher:410 - about to open PreparedStatement (open PreparedStatements: 300, globally: 300)
15:52:11,430 DEBUG SQL:111 - select tinstantal0_.ACCT_ID as ACCT1_20_, tinstantal0_.PER_ID as PER2_20_, tinstantal0_.PREM_ID as PREM3_20_, tinstantal0_.SP_ID as SP4_20_, tinstantal0_.SP_TYPE_CD as SP5_20_, tinstantal0_.ENTITY_NAME as ENTITY6_20_, tinstantal0_.EMAILID as EMAILID20_, tinstantal0_.PHONE as PHONE20_, tinstantal0_.PHONE_TYPE as PHONE9_20_, tinstantal0_.OD_OPTION_SW as OD10_20_, tinstantal0_.ODE_OPTION_SW as ODE11_20_, tinstantal0_.ADDRESS1 as ADDRESS12_20_ from InstantAlert.T_INSTANT_ALERT_LOOKUP_VW tinstantal0_ where sp_id=? and (phone_type=? or phone_type=? or phone_type=?) order by length(phone_type)
15:52:11,524 DEBUG AbstractBatcher:418 - about to close PreparedStatement (open PreparedStatements: 301, globally: 301)
15:52:11,524 DEBUG JDBCExceptionReporter:92 - could not execute query [select tinstantal0_.ACCT_ID as ACCT1_20_, tinstantal0_.PER_ID as PER2_20_, tinstantal0_.PREM_ID as PREM3_20_, tinstantal0_.SP_ID as SP4_20_, tinstantal0_.SP_TYPE_CD as SP5_20_, tinstantal0_.ENTITY_NAME as ENTITY6_20_, tinstantal0_.EMAILID as EMAILID20_, tinstantal0_.PHONE as PHONE20_, tinstantal0_.PHONE_TYPE as PHONE9_20_, tinstantal0_.OD_OPTION_SW as OD10_20_, tinstantal0_.ODE_OPTION_SW as ODE11_20_, tinstantal0_.ADDRESS1 as ADDRESS12_20_ from InstantAlert.T_INSTANT_ALERT_LOOKUP_VW tinstantal0_ where sp_id=? and (phone_type=? or phone_type=? or phone_type=?) order by length(phone_type)]
java.sql.SQLException: ORA-01000: maximum open cursors exceeded
at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:187)
at oracle.jdbc.ttc7.TTIoer.processError(TTIoer.java:241)
at oracle.jdbc.ttc7.Oopen.receive(Oopen.java:118)
at oracle.jdbc.ttc7.TTC7Protocol.open(TTC7Protocol.java:498)
at oracle.jdbc.driver.OracleStatement.open(OracleStatement.java:678)
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:2499)
at oracle.jdbc.driver.OraclePreparedStatement.executeUpdate(OraclePreparedStatement.java:452)
at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:382)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
at org.hibernate.loader.Loader.getResultSet(Loader.java:1812)
at org.hibernate.loader.Loader.doQuery(Loader.java:697)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
at org.hibernate.loader.Loader.doList(Loader.java:2232)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2129)
at org.hibernate.loader.Loader.list(Loader.java:2124)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:401)
at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:363)
at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1149)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
at us.fl.ci.tlh.uu.notification.persistence.cis.TInstantAlertLookupDAO.populateExternalNotificationBasedOnSpid(TInstantAlertLookupDAO.java:208)
at us.fl.ci.tlh.uu.notification.business.ExternalNotificationBusinessHelper.populateNotificationsWithCisInformation(ExternalNotificationBusinessHelper.java:312)
at us.fl.ci.tlh.uu.notification.quartz.scheduledtasks.electric.GetOutageInformation.execute(GetOutageInformation.java:111)
at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
*************************************************************
Bam! This isn't a one to one; i.e., I can usually process around 3,000 records before I hit the magical 300 value for number of allowable open cursors. Based on other comments in this thread, I scanned for other errors, but it doesn't look as if anything is being reported, I certaily have catch / logging blocks in the affeced areas.
Is there any chance I could start to accumulate open cursors if I did something like this:
Iterator it = theQueryIRun.iterate();
while (it.hasNext()){
if (checkForCondition()){
break;
}
}
i.e., if I don't loop through everyhing in my result set? There are some data specific patterns that cause my code to occassionally break out from the loop. Are these unevaluated result sets, perhaps the source of my open cursors?
Any insight is appreciated!
brian
July 22, 2011 - 2:04 pm UTC
query v$open-cursor, it'll show you what is still open.
You have an exception block somewhere in your code that is leaking a cursor handle, I've seen it so often that I'm 99.999999999% sure this is the case.
have a routine that you can call to dump out to your debug log a list of cursors you have open. call this routine frequently - and in your error log, you should see the list of cursors that are still open and growing.
(also, how is your statement caching setup for your jdbc driver? could it be to blame?)