Solved

Inbound Connection Timeouts

Posted on 2013-11-14
6
777 Views
Last Modified: 2013-11-15
We too frequently experience a situation where the application for some unknown reason saturates the database connections and grinds to effectively a halt.  Below i've posted some of the SQL type errors that preceded the most recent occurrence.  At about 7:30 we see the final ORA- integrity constraint error and about 45 minutes later, the 1400 or so inbound connection timeouts occur.    An operator states the the system froze, then came back up then went down again.  I know the lead made the decision to restart the system.  I am wondering if it was during the time the 1400 inbound connection timeouts that the operator noticed the system came back up, then went back down when the lead restarted the application, including the database??   In other words are the inbound connection timeouts signaling a tied up connection to the database being released?
Also there was a lot of UNDO usage during the period if all the inbound connection timeouts.  Could this undo activity be related to rollback activity from all the ORA-02291 errors??


013-10-30 01:28:30 -0700 - BEGIN course_toc_cr ( crsmain_pk1 =>  [ 373509 ] , course_contents_pk1 =>  [ 2 ] , label =>  [ Blogs ] , href =>  [ 12 ] , target_type =>  [ APPLICATIO... ] , position =>  [ 0 ] , launch_ind =>  [ Y ] , enabled_ind =>  [ N ] , entry_point_ind =>  [ N ] , allow_observer_ind =>  [ N ] , internal_handle =>  [ lobj-lobj_... ] , allow_guest_ind =>  [ N ] , pk1 =>  ); END;  failed. - java.sql.SQLIntegrityConstraintViolationException: ORA-02291: integrity constraint (BB_BB60.COURSE_TOC_FK3) violated - parent key not found
ORA-06512: at "BB_BB60.COURSE_TOC_CR", line 60
ORA-06512: at line 1

"
"
This error recurs several dozen times until:

2013-10-30 01:29:05 -0700 - INSERT INTO group_application ( groups_pk1,application,pk1 ) VALUES (  [ 45709 ] , [ lobj-campu... ] ,group_application_seq.nextval ) failed. - java.sql.SQLIntegrityConstraintViolationException: ORA-02291: integrity constraint (BB_BB60.GROUP_APPLICATION_FK1) violated - parent key not found

2013-10-30 01:29:05 -0700 - INSERT INTO group_application ( groups_pk1,application,pk1 ) VALUES (  [ 45709 ] , [ lobj-campu... ] ,group_application_seq.nextval ) failed. - java.sql.SQLIntegrityConstraintViolationException: ORA-02291: integrity constraint (BB_BB60.GROUP_APPLICATION_FK1) violated - parent key not found

2013-10-30 01:29:05 -0700 - INSERT INTO group_application ( groups_pk1,application,pk1 ) VALUES (  [ 45709 ] , [ lobj-campu... ] ,group_application_seq.nextval ) failed. - java.sql.SQLIntegrityConstraintViolationException: ORA-02291: integrity constraint (BB_BB60.GROUP_APPLICATION_FK1) violated - parent key not found

...
occurs three more times

2013-10-30 03:27:26 -0700 - BEGIN system_registry_cr ( registry_key =>  [ SingletonW... ] , registry_value =>  [ 1383128846... ] , permissions =>  [ Y ] , description =>  [ 12 ] , registry_long_value =>  [ 12 ] , pk1 =>  ); END;  failed. - java.sql.SQLIntegrityConstraintViolationException: ORA-00001: unique constraint (BB_BB60.SYSTEM_REGISTRY_AK) violated
ORA-06512: at "BB_BB60.SYSTEM_REGISTRY_CR", line 34
ORA-06512: at line 1

	at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:440)

2013-10-30 05:27:26 -0700 - BEGIN system_registry_cr ( registry_key =>  [ SingletonW... ] , registry_value =>  [ 1383136046... ] , permissions =>  [ Y ] , description =>  [ 12 ] , registry_long_value =>  [ 12 ] , pk1 =>  ); END;  failed. - java.sql.SQLIntegrityConstraintViolationException: ORA-00001: unique constraint (BB_BB60.SYSTEM_REGISTRY_AK) violated
ORA-06512: at "BB_BB60.SYSTEM_REGISTRY_CR", line 34
ORA-06512: at line 1

2013-10-30 05:56:27 -0700 - UPDATE attempt SET grade =  [           ... ] , score =  [ 0.0 ] , comment_public_ind =  [ Y ] , status =  [ 7 ] , exempt_ind =  [ N ] , group_attempt_pk1 =  [ 2 ] , student_comments =  [ 12 ] , override_ind =  [ N ] , student_submission =  [ 12 ] , text_format_type =  [ 12 ]  WHERE pk1 =  [ 9091632 ]  failed. - java.sql.SQLException: ORA-12899: value too large for column "BB_BB60"."ATTEMPT"."GRADE" (actual: 49, maximum: 32)

[b]2013-10-30 07:27:26 -0700 - [/b]BEGIN system_registry_cr ( registry_key =>  [ SingletonW... ] , registry_value =>  [ 1383143246... ] , permissions =>  [ Y ] , description =>  [ 12 ] , registry_long_value =>  [ 12 ] , pk1 =>  ); END;  failed. - java.sql.SQLIntegrityConstraintViolationException: ORA-00001: unique constraint (BB_BB60.SYSTEM_REGISTRY_AK) violated
ORA-06512: at "BB_BB60.SYSTEM_REGISTRY_CR", line 34
ORA-06512: at line 1

at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:440)
	at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:396)
	at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:837)
	at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:445)
	at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:191)
	at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:523)
	at oracle.jdbc.driver.T4CCallableStatement.doOall8(T4CCallableStatement.java:204)
	at oracle.jdbc.driver.T4CCallableStatement.executeForRows(T4CCallableStatement.java:1007)
	at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1315)
	at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3576)
	at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3677)
	at oracle.jdbc.driver.OracleCallableStatement.execute(OracleCallableStatement.java:4714)
	at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1374)
	at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
	at blackboard.db.impl.MonitoringConnectionPoolImpl$SQLRecorder.execute(MonitoringConnectionPoolImpl.java:203)
	at blackboard.db.impl.MonitoringConnectionPoolImpl$MonitoringCallableStatement.execute(MonitoringConnectionPoolImpl.java:631)
	at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
	at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
	at blackboard.db.impl.SafetyNetCallableStatement.execute(SafetyNetCallableStatement.java:52)
	at blackboard.persist.impl.StoredProcedureQuery.doExecute(StoredProcedureQuery.java:365)
	at blackboard.persist.impl.GenericProcedureQuery.doExecute(GenericProcedureQuery.java:213)
	at blackboard.persist.impl.Query.executeQuery(Query.java:121)
	at blackboard.persist.impl.AbstractBaseDbPersister$DbConnectivityPrivilege.run(AbstractBaseDbPersister.java:253)
	at java.security.AccessController.doPrivileged(Native Method)
	at blackboard.persist.impl.AbstractBaseDbPersister.runQuery(AbstractBaseDbPersister.java:159)
	at blackboard.persist.impl.NewBaseDbPersister.doInsert(NewBaseDbPersister.java:127)
	at blackboard.persist.impl.NewBaseDbPersister.doPersist(NewBaseDbPersister.java:75)
	at blackboard.persist.registry.impl.SystemRegistryEntryDbPersisterImpl.persist(SystemRegistryEntryDbPersisterImpl.java:44)
	at blackboard.persist.registry.impl.SystemRegistryEntryDbPersisterImpl.persist(SystemRegistryEntryDbPersisterImpl.java:38)
	at com.blackboard.registration.util.SystemRegistryDAO.lockRow(SystemRegistryDAO.java:155)
	at com.blackboard.registration.util.SingletonWithMaxTimeManager.doExecute(SingletonWithMaxTimeManager.java:41)
	at com.blackboard.registration.util.SingletonWithMaxTimeManager.execute(SingletonWithMaxTimeManager.java:26)
	at com.blackboard.registration.impl.RegistrationTimerTask.runTask(RegistrationTimerTask.java:37)
	at blackboard.platform.impl.services.task.VISpecificTimerTask.run(VISpecificTimerTask.java:70)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)
********   First inbound connection timeout shows in alert log ************* 
            followed by almost 1400 timeouts in the next 30 - 40 minutes
****************************************************************

***********************************************************************************************************************
WARNING: inbound connection timed out (ORA-3136)
    nt secondary err code: 0
    nt OS err code: 0
  Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=172.22.119.94)(PORT=56232))
 
WARNING: inbound connection timed out (ORA-3136)
Wed Oct 30 08:13:25 2013
 ****   also on .92, .93 and .95
 
 Between 8:13 and about 9:00 1375 inbound connect timeouts.

***********************************************************************************************************************
2013-10-30 08:14:31 -0700 - blackboard.persist.impl.SimpleSelectQuery@311766ff failed. - blackboard.db.ConnectionNotAvailableException: IO Error: Connection reset
	at blackboard.db.impl.DataSourcePoolImpl.getConnection(DataSourcePoolImpl.java:94)
	at blackboard.db.impl.AbstractOracleConnectionPool.getConnection(AbstractOracleConnectionPool.java:63)
	
	Caused by: java.sql.SQLRecoverableException: IO Error: Connection reset
	
	Caused by: java.net.SocketException: Connection reset
		at java.net.SocketInputStream.read(SocketInputStream.java:189)
		
		
2013-10-30 08:14:31 -0700 - SELECT count(*) FROM peer_service p WHERE (p.inactive_ind=? AND p.node_id=?) failed. - blackboard.db.ConnectionNotAvailableException: IO Error: Connection reset
	at blackboard.db.impl.DataSourcePoolImpl.getConnection(DataSourcePoolImpl.java:94)



	Caused by: java.sql.SQLRecoverableException: IO Error: Connection reset
	
	Caused by: java.net.SocketException: Connection reset
	
	2013-10-30 08:14:31 -0700 - blackboard.portal.servlet.HealthCheckServlet$HealthCheckQuery@2b88a27d failed. - blackboard.db.ConnectionNotAvailableException: IO Error: Connection reset
		at blackboard.db.impl.DataSourcePoolImpl.getConnection(DataSourcePoolImpl.java:94)
		
		......more connection problems....
		
2013-10-30 08:14:31 -0700 - blackboard.persist.impl.CacheTokenUtil$LoadSignalTimesQuery@441bbd63 failed. - blackboard.db.ConnectionNotAvailableException: IO Error: Connection reset
		
Caused by: java.sql.SQLRecoverableException: IO Error: Connection reset
	at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:428)
	at oracle.jdbc.driver.PhysicalConnection.<init>(PhysicalConnection.java:536)
		
2013-10-30 08:14:32 -0700 - blackboard.persist.impl.external.ExternalSelectQuery@7ee7efce failed. - blackboard.db.ConnectionNotAvailableException: IO Error: Connection reset
2013-10-30 08:14:42 -0700 - blackboard.persist.course.impl.CourseDbLoaderImpl$LoadByUserIdQuery@1c53db5c failed. - blackboard.db.ConnectionNotAvailableException: IO Error: Connection reset


........more connection fails.
.
.
Caused by: oracle.net.ns.NetException: The Network Adapter could not establish the connection
	at oracle.net.nt.ConnStrategy.execute(ConnStrategy.java:375)


2013-10-30 08:14:43 -0700 - blackboard.persist.impl.SimpleSelectQuery@21c3458f failed. - blackboard.db.ConnectionNotAvailableException: IO Error: Connection reset

	
Caused by: java.sql.SQLRecoverableException: IO Error: The Network Adapter could not establish the connection
	at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:419)

Open in new window

0
Comment
Question by:xoxomos
  • 2
  • 2
6 Comments
 
LVL 76

Accepted Solution

by:
slightwv (䄆 Netminder) earned 300 total points
ID: 39649739
The answer to all your questions is: It could be all related.

If a transaction fails it likely rolls back.  The timeouts could be due to a busy system that is tied up doing to many rollbacks.

The unique/primary constraint violations tells me there is likely a serious problem with the app.  The ORA-12899 should also never be possible if the application is properly coded.

You might be able to look at all the wait events and overall performance metrics to try and figure out what is causing the timeouts but personally I would spend time trying to fix the other errors and see if the timeouts magically go away.
0
 

Author Comment

by:xoxomos
ID: 39649798
"The ORA-12899 should also never be possible if the application is properly coded."
AMEN Bro!!! AMEN, AMEN. I get the feeling they're not believing that when I put it to them
:-)
 :-(
Could the 'timeout' part of 'inbound connection timeout result in freeing of connections that had been tied up????  The number of timeouts was almost all of the connections coming from all the app servers combined.
0
 
LVL 76

Expert Comment

by:slightwv (䄆 Netminder)
ID: 39649828
>>result in freeing of connections that had been tied up

Not sure.  I suppose anything is possible.  This would probably be an excellent question or Oracle Support.

Why I'm not sure is that if the processes init parameter has been reached so no new connections can be spawned and Oracle thinks some of the existing connections can be 'cleaned up' will it wait until they are freed?

Seems possible since otherwise I would expect a http://ora-00020.ora-code.com/

It's a decent theory.  Again, check with Oracle to confirm.

I would also wait for other Experts to post what they know.
0
 
LVL 36

Expert Comment

by:Geert Gruwez
ID: 39650425
Are so many connections coming from different apps or just 1 ?
is it possible the app needs to process a workload and thinks it needs that many connections ? > just a sample: bizztalk can have this behaviour
if so, either ask them to limit their connection
or setup shared server if they can't
> you can setup shared server and have only a specific set of apps use it
others can still work dedicated

or the code is badly written for multiuser processing

if in archivelog mode, does your archive destination fill up ?
this could describe the system coming back up after some cleanup is done on the archivelogs
0
 

Author Closing Comment

by:xoxomos
ID: 39651691
Mil gracias
0

Featured Post

PRTG Network Monitor: Intuitive Network Monitoring

Network Monitoring is essential to ensure that computer systems and network devices are running. Use PRTG to monitor LANs, servers, websites, applications and devices, bandwidth, virtual environments, remote systems, IoT, and many more. PRTG is easy to set up & use.

Join & Write a Comment

Working with Network Access Control Lists in Oracle 11g (part 2) Part 1: http://www.e-e.com/A_8429.html Previously, I introduced the basics of network ACL's including how to create, delete and modify entries to allow and deny access.  For many…
Have you ever had to make fundamental changes to a table in Oracle, but haven't been able to get any downtime?  I'm talking things like: * Dropping columns * Shrinking allocated space * Removing chained blocks and restoring the PCTFREE * Re-or…
This video explains at a high level with the mandatory Oracle Memory processes are as well as touching on some of the more common optional ones.
Via a live example, show how to take different types of Oracle backups using RMAN.

747 members asked questions and received personalized solutions in the past 7 days.

Join the community of 500,000 technology professionals and ask your questions.

Join & Ask a Question

Need Help in Real-Time?

Connect with top rated Experts

13 Experts available now in Live!

Get 1:1 Help Now