Saturday, October 22, 2011

HIGH CPU USAGE PROBLEM WITH AGGRESPY(SPY) applied on the top of SOA 10.1.3.4

Visit the Below Website to access unlimited exam questions for all IT vendors and Get Oracle Certifications for FREE
http://www.free-online-exams.com

Problem:

HIGH CPU USAGE PROBLEM WITH AGGRESPY(SPY) applied on the top of SOA 10.1.3.4

Symptoms:
opmn.log shows  SOA components are continuously restarting.

Log files:
Opmn.log
opmn.log:8526:09/04/11 14:23:45 [libopmnoc4j] OC4J ping attempt timed out
opmn.log:8528:09/04/12 08:26:34 [libopmnoc4j] OC4J ping attempt timed out
opmn.log:8530:09/04/12 08:27:24 [libopmnoc4j] OC4J ping attempt timed out
opmn.log:8532:09/04/12 08:28:14 [libopmnoc4j] OC4J ping attempt timed out
opmn.log:8534:09/04/12 08:29:04 [libopmnoc4j] OC4J ping attempt timed out
opmn.log:8536:09/04/12 08:29:54 [libopmnoc4j] OC4J ping attempt timed out
opmn.log:8538:09/04/12 08:30:44 [libopmnoc4j] OC4J ping attempt timed out
opmn.log:8546:09/04/22 10:06:11 [libopmnoc4j] OC4J ping attempt timed out
opmn.log:8548:09/04/22 10:07:01 [libopmnoc4j] OC4J ping attempt timed out
opmn.log:8550:09/04/22 10:07:51 [libopmnoc4j] OC4J ping attempt timed out
opmn.log:8552:09/04/22 10:08:41 [libopmnoc4j] OC4J ping attempt timed out
opmn.log:8554:09/04/22 10:09:31 [libopmnoc4j] OC4J ping attempt timed out
opmn.log:8556:09/04/22 10:10:21 [libopmnoc4j] OC4J ping attempt timed out

BPEL~oc4j_soa~default_group~1.log


Group is not found.
Group "group" is not found in realm "jazn.com"
Please, verify that given group name "group" exists in realm "jazn.com". Check the error stack and fix the cause of the error. Contact oracle support if error is not fixable.

at oracle.tip.pc.services.identity.jazn.BPMAuthorizationServiceImpl.lookupGroup(BPMAuthorizationServiceImpl.java:235)
at oracle.tip.pc.services.identity.jazn.xml.XMLIdentityService.lookupGroup(XMLIdentityService.java:175)
at oracle.bpel.services.workflow.task.impl.TaskUtil.getUsersinAsssignment(TaskUtil.java:185)
at oracle.bpel.services.workflow.task.impl.TaskUtil.randomPickCurrentAssignee(TaskUtil.java:156)
at oracle.bpel.services.workflow.task.impl.TaskUtil.randomPickCurrentAssignee(TaskUtil.java:143)
at oracle.bpel.services.workflow.task.impl.TaskUtil.getCurrentAssignee(TaskUtil.java:131)
at oracle.bpel.services.workflow.verification.impl.VerificationService.isTopmostUser(VerificationService.java:2915)
at oracle.bpel.services.workflow.verification.impl.VerificationService.getRoleBasedGroupActions(VerificationService.java:2649)
at oracle.bpel.services.workflow.verification.impl.VerificationService.getTaskSystemActions(VerificationService.java:1257)
...
<2009-04-20 14:53:33,485> <WARN> <default.collaxa.cube.services> <::> The value parameter passed in Predicate.addClause contains Strings, and will be deprecated. Please pass List of ITaskAssingee.
09/04/20 14:53:41 Remote User is: null------------------------------------------
09/04/20 14:53:41 Normal login with username: User------------------------------------------
09/04/20 14:54:45 Remote User is: null------------------------------------------
09/04/20 14:54:48 Remote User is: null------------------------------------------
09/04/20 14:54:48 Normal login with username: User------------------------------------------
09/04/20 14:54:48 Remote User is: null------------------------------------------
09/04/20 14:55:13 Remote User is: null------------------------------------------
09/04/20 14:55:13 Normal login with username: User------------------------------------------
<2009-04-20 14:55:13,258> <ERROR> <declaration.collaxa.cube.services> <PCException::<init>> Identity Service Authentication failure.
<2009-04-20 14:55:13,258> <ERROR> <declaration.collaxa.cube.services> <PCException::<init>> Identity Service Authentication failure.
<2009-04-20 14:55:13,259> <ERROR> <declaration.collaxa.cube.services> <PCException::<init>> Check the error stack and fix the cause of the error. Contact oracle support if error is not fixable.
<2009-04-20 14:55:13,259> <ERROR> <declaration.collaxa.cube.services> <::> WorkflowService:: VerificationService.authenticateUser: error: Identity Service Authentication failure.
<2009-04-20 14:55:13,259> <ERROR> <declaration.collaxa.cube.services> <::> Identity Service Authentication failure.
<2009-04-20 14:55:13,259> <ERROR> <declaration.collaxa.cube.services> <::> Check the error stack and fix the cause of the error. Contact oracle support if error is not fixable.
<2009-04-20 14:55:13,259> <ERROR> <declaration.collaxa.cube.services> <::> ORABPEL-30501
<2009-04-20 14:55:13,259> <ERROR> <declaration.collaxa.cube.services> <::>
<2009-04-20 14:55:13,259> <ERROR> <declaration.collaxa.cube.services> <::> Error in authenticating user.
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> Error in authenticating and creating a workflow context for user jazn.com/User
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> Check the underlying exception and correct the error. Contact oracle support if error is not fixable.
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::>
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> at oracle.bpel.services.workflow.verification.impl.VerificationService.authenticateUser(VerificationService.java:375)
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> at oracle.bpel.services.workflow.query.impl.TaskQueryService.authenticate(TaskQueryService.java:159)
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> at worklistapp.servlets.Login.handleRequest(Login.java:137)
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> at worklistapp.servlets.BaseServlet.doPost(BaseServlet.java:157)
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> at javax.servlet.http.HttpServlet.service(HttpServlet.java:763)
...
...
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> at com.evermind.util.ReleasableResourcePooledExecutor$MyWorker.run(ReleasableResourcePooledExecutor.java:303)
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> at java.lang.Thread.run(Thread.java:595)
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> Caused by: ORABPEL-10528
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::>
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> Identity Service Authentication failure.
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> Identity Service Authentication failure.
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> Check the error stack and fix the cause of the error. Contact oracle support if error is not fixable.
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::>
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> at oracle.tip.pc.services.identity.jazn.xml.XMLAuthenticationService.authenticateUser(XMLAuthenticationService.java:150)
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> at oracle.tip.pc.services.identity.jazn.xml.XMLIdentityService.authenticateUser(XMLIdentityService.java:426)
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> at oracle.bpel.services.workflow.verification.impl.VerificationService.authenticateUser(VerificationService.java:341)
<2009-04-20 14:55:13,260> <ERROR> <declaration.collaxa.cube.services> <::> ... 14 more
<2009-04-20 14:55:13,260> <ERROR> <oracle.bpel.services.workflow> <::> Identity Service Authentication failure.
Identity Service Authentication failure.
Check the error stack and fix the cause of the error. Contact oracle support if error is not fixable.

ORABPEL-10528

Identity Service Authentication failure.
Identity Service Authentication failure.

Check the error stack and fix the cause of the error. Contact oracle support if error is not fixable.

at oracle.tip.pc.services.identity.jazn.xml.XMLAuthenticationService.authenticateUser(XMLAuthenticationService.java:150)
at oracle.tip.pc.services.identity.jazn.xml.XMLIdentityService.authenticateUser(XMLIdentityService.java:426)
at oracle.bpel.services.workflow.verification.impl.VerificationService.authenticateUser(VerificationService.java:341)
at oracle.bpel.services.workflow.query.impl.TaskQueryService.authenticate(TaskQueryService.java:159)
at worklistapp.servlets.Login.handleRequest(Login.java:137)
at worklistapp.servlets.BaseServlet.doPost(BaseServlet.java:157)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:763)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:856)
at com.evermind.server.http.ServletRequestDispatcher.invoke(ServletRequestDispatcher.java:713)
at com.evermind.server.http.ServletRequestDispatcher.forwardInternal(ServletRequestDispatcher.java:370)
at com.evermind.server.http.HttpRequestHandler.doProcessRequest(HttpRequestHandler.java:871)
at com.evermind.server.http.HttpRequestHandler.processRequest(HttpRequestHandler.java:453)
at com.evermind.server.http.AJPRequestHandler.run(AJPRequestHandler.java:313)
at com.evermind.server.http.AJPRequestHandler.run(AJPRequestHandler.java:199)
at oracle.oc4j.network.ServerSocketReadHandler$SafeRunnable.run(ServerSocketReadHandler.java:260)
at com.evermind.util.ReleasableResourcePooledExecutor$MyWorker.run(ReleasableResourcePooledExecutor.java:303)
at java.lang.Thread.run(Thread.java:595)
09/04/20 14:55:15 Remote User is: null------------------------------------------
09/04/20 14:55:15 Normal login with username: User------------------------------------------
...


~SOA_~default_group~1.log

...
09/04/20 14:49:09 Caused by: org.hibernate.TransactionException: JDBC rollback failed
09/04/20 14:49:09 at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:170)
09/04/20 14:49:09 at org.springframework.orm.hibernate3.HibernateTransactionManager.doRollback(HibernateTransactionManager.java:589)
09/04/20 14:49:09 at org.springframework.transaction.support.AbstractPlatformTransactionManager.doRollbackOnCommitException(AbstractPlatformTransactionManager.java:792)
09/04/20 14:49:09 at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:679)
09/04/20 14:49:09 at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:621)
09/04/20 14:49:09 at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:311)
09/04/20 14:49:09 at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:117)
09/04/20 14:49:09 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
09/04/20 14:49:09 at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
09/04/20 14:49:09 at $Proxy135.saveUploadedDocument(Unknown Source)
09/04/20 14:49:09 at sun.reflect.GeneratedMethodAccessor15030.invoke(Unknown Source)
09/04/20 14:49:09 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
09/04/20 14:49:09 at java.lang.reflect.Method.invoke(Method.java:585)
09/04/20 14:49:09 at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:299)
09/04/20 14:49:09 at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:172)
09/04/20 14:49:09 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:139)
09/04/20 14:49:09 at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:107)
09/04/20 14:49:09 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
09/04/20 14:49:09 at com.ksevindik.auditing.interceptor.ServiceAuditLogInterceptor.invoke(ServiceAuditLogInterceptor.java:43)
09/04/20 14:49:09 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
09/04/20 14:49:09 at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
09/04/20 14:49:09 at $Proxy136.saveUploadedDocument(Unknown Source)
09/04/20 14:49:09 at com.pcfc.customs.customer.common.web.action.UploadDocumentAction.executeInvokeMethod(UploadDocumentAction.java:410)
09/04/20 14:49:09 ... 41 more
09/04/20 14:49:09 Caused by: java.sql.SQLException: Attempt to use an invalid handle : 'oracle_jdbc_driver_LogicalConnection_Proxy@278340'.
09/04/20 14:49:09 at oracle.oc4j.sql.spi.ConnectionHandle.oc4j_intercept(ConnectionHandle.java:286)
09/04/20 14:49:09 at oracle.oc4j.sql.spi.ConnectionHandle.rollback(ConnectionHandle.java:148)
09/04/20 14:49:09 at org.hibernate.transaction.JDBCTransaction.rollbackAndResetAutoCommit(JDBCTransaction.java:183)
09/04/20 14:49:09 at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:162)
09/04/20 14:49:09 ... 63 more

 BPEL~oc4j_soa~default_group~2.log

....
<2009-04-01 19:05:15,163> <ERROR> <declaration.collaxa.cube.engine.dispatch> <BaseScheduledWorker::process> Failed to handle dispatch message ... exception ORABPEL-05002

Message handle error.
An exception occurred while attempting to process the message "com.collaxa.cube.engine.dispatch.message.instance.ExpirationMessage"; the exception is: Instance not found in datasource.
The process domain was unable to fetch the instance with key "11701441" from the datasource.
Please check that the instance key "11701441" refers to a valid instance that has been started and not removed from the process domain.


ORABPEL-05002

Message handle error.
An exception occurred while attempting to process the message "com.collaxa.cube.engine.dispatch.message.instance.ExpirationMessage"; the exception is: Instance not found in datasource.
The process domain was unable to fetch the instance with key "11701441" from the datasource.
Please check that the instance key "11701441" refers to a valid instance that has been started and not removed from the process domain.


at com.collaxa.cube.engine.dispatch.DispatchHelper.handleMessage(DispatchHelper.java:171)
at com.collaxa.cube.engine.dispatch.BaseScheduledWorker.process(BaseScheduledWorker.java:70)
at com.collaxa.cube.engine.ejb.impl.WorkerBean.onMessage(WorkerBean.java:86)
at sun.reflect.GeneratedMethodAccessor51.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at com.evermind.server.ejb.interceptor.joinpoint.EJBJoinPointImpl.invoke(EJBJoinPointImpl.java:35)
at com.evermind.server.ejb.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:119)
at com.evermind.server.ejb.interceptor.system.DMSInterceptor.invoke(DMSInterceptor.java:52)
at com.evermind.server.ejb.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:119)
at com.evermind.server.ejb.interceptor.system.SetContextActionInterceptor.invoke(SetContextActionInterceptor.java:44)
at com.evermind.server.ejb.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:119)
at com.evermind.server.ejb.InvocationContextPool.invoke(InvocationContextPool.java:55)
at oracle.j2ee.connector.messageinflow.MessageEndpointImpl.OC4J_invokeMethod(MessageEndpointImpl.java:297)
at WorkerBean_EndPointProxy_4bin6i8.onMessage(Unknown Source)
at oracle.j2ee.ra.jms.generic.WorkConsumer.run(WorkConsumer.java:266)
at oracle.j2ee.connector.work.WorkWrapper.runTargetWork(WorkWrapper.java:242)
at oracle.j2ee.connector.work.WorkWrapper.doWork(WorkWrapper.java:215)
at oracle.j2ee.connector.work.WorkWrapper.run(WorkWrapper.java:190)
at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:814)
at java.lang.Thread.run(Thread.java:595)
09/04/01 22:32:22 pFaultMessage is org.collaxa.thirdparty.apache.wsif.base.WSIFDefaultMessage@1bf36ff name:DPPException
09/04/01 22:32:22 QName string is DPPException
09/04/01 22:32:22 pFaultMessage is org.collaxa.thirdparty.apache.wsif.base.WSIFDefaultMessage@1bcca5d name:DPPException
09/04/01 22:32:22 QName string is DPPException
09/04/01 22:32:40 pFaultMessage is org.collaxa.thirdparty.apache.wsif.base.WSIFDefaultMessage@1de9d38 name:DPPException
09/04/01 22:32:40 QName string is DPPException

--------
09/04/01 23:14:20 Stop process
--------
09/04/01 23:14:41 Shutting down...

<2009-04-01 23:14:44,618> <INFO> <collaxa> <ServerManager::uninit> Shutting down all domains
<2009-04-01 23:14:45,810> <INFO> <default.collaxa.cube.engine> <AdapterStats::uninit:Done uninitializing Adapter statistics holder for engine > default
<2009-04-01 23:14:45,837> <INFO> <default.collaxa.cube.engine> <AdaptorManager::unload> Uninitialized adaptors for platform 'ias_10g', datasource 'oracle'
<2009-04-01 23:14:45,837> <INFO> <default.collaxa.cube.engine> <CubeEngine::uninit> Uninitialized BPEL domain "default"
<2009-04-01 23:14:45,837> <INFO> <default.collaxa.cube.engine> <CubeEngine::unload> Unloaded BPEL domain "default"
<2009-04-01 23:14:46,652> <INFO> <collaxa> <ServerManager::uninit> Done shutting down all domains
Apr 1, 2009 11:14:47 PM org.collaxa.thirdparty.jgroups.blocks.PullPushAdapter run
WARNING: [<null>] channel closed, exception is ChannelClosedException
09/04/01 23:16:19 WARNING: MessageDrivenHome.waitForListeners Timeout waiting for listener threads to finish

Solution:
Patch 7670088: HIGH CPU USAGE PROBLEM WITH AGGRESPY(SPY) applied on the top of SOA 10.1.3.4 MLR# 6 installation

References:

Note. 761675.1 " OracleAS 10g OPMN Restarts OC4J Instance After "OC4J Ping Attempt Timed Out" Error "
Get Oracle Certifications for all Exams
Free Online Exams.com

No comments: