[GLASSFISH-14917] [BLOCKING] [PERF] http thread pool totally blocked server not responsive to http traffic Created: 01/Dec/10  Updated: 09/Dec/10  Resolved: 09/Dec/10

Status: Resolved
Project: glassfish
Component/s: naming, orb
Affects Version/s: 3.1_b31
Fix Version/s: 3.1_ms07

Type: Bug Priority: Blocker
Reporter: Stephen DiMilla Assignee: Ken Cavanaugh
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

all


Attachments: File jstack.out     File jstack.out2     Text File jstack_trade2-0-1.txt     Text File jstack_trade2-1-1.txt     File orb.tgz     File orb2.tgz     Text File server.log     Zip Archive trade2-1-1_logs.zip     Text File trade2_instance1_server_dec6.log     Text File trade2_instance2_server_dec6.log    

 Description   

This is blocking Trade2 performance runs. It is an intermittent issue and does not happen all the time.
This issue has been occurring since the nightly builds of Nov 18th.
The only workaround is to run multiple times to get around the intermitent behavior.

We have taken 2 jstack (taken at different times) of the non responsive server and attached them along
with the server log of the affected instance.

The following is a sample of the 37 blocked http threads:

"http-thread-pool-8080(15)" daemon prio=10 tid=0x00002aaab8ee7800 nid=0x945 waiting on condition [0x0000000043720000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)

  • parking to wait for <0x00000006e6c0a0a0> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:941)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1261)
    at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:594)
    at com.sun.corba.ee.impl.oa.poa.POAImpl.readLock(POAImpl.java:387)
    at com.sun.corba.ee.impl.oa.poa.POAImpl.find_POA(POAImpl.java:950)
    at com.sun.corba.ee.impl.oa.rfm.ReferenceFactoryManagerImpl.createReference(ReferenceFactoryManagerImpl.java:546)
    at com.sun.corba.ee.impl.oa.rfm.ReferenceFactoryImpl.createReference(ReferenceFactoryImpl.java:62)
    at org.glassfish.enterprise.iiop.impl.POARemoteReferenceFactory._createRef(POARemoteReferenceFactory.java:439)
    at org.glassfish.enterprise.iiop.impl.POARemoteReferenceFactory.createRef(POARemoteReferenceFactory.java:402)
    at org.glassfish.enterprise.iiop.impl.POARemoteReferenceFactory.createRemoteReference(POARemoteReferenceFactory.java:366)
    at com.sun.ejb.containers.EntityContainer.getEJBObjectStub(EntityContainer.java:1819)
    at com.sun.ejb.containers.EntityContainer.postFind(EntityContainer.java:889)
    at com.sun.ejb.containers.EJBHomeInvocationHandler.invoke(EJBHomeInvocationHandler.java:314)
    at $Proxy183.findByUserID(Unknown Source)


 Comments   
Comment by Cheng Fang [ 01/Dec/10 ]

Re-assign to Ken for evaluation, as the exception is from orb.

Comment by Stephen DiMilla [ 01/Dec/10 ]

FYI: There is several exceptions in the server log but not sure if they are related to this issue.
The first one is:
[#|2010-12-01T17:03:22.388+0000|WARNING|glassfish3.1|javax.enterprise.resource.corba.POA|_ThreadID=15;_ThreadName=Thread-1;|IOP02310823: ReferenceFactoryManager caught exception in AdapterActivator.unknown_adaptor
org.omg.CORBA.OBJ_ADAPTER: WARNING: IOP02310823: ReferenceFactoryManager caught exception in AdapterActivator.unknown_adaptor vmcid: OMG minor code: 823 completed: No
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at com.sun.corba.ee.spi.orbutil.logex.corba.CorbaExtension.makeException(CorbaExtension.java:248)
at com.sun.corba.ee.spi.orbutil.logex.corba.CorbaExtension.makeException(CorbaExtension.java:95)
at com.sun.corba.ee.spi.orbutil.logex.WrapperGenerator.handleFullLogging(WrapperGenerator.java:422)
at com.sun.corba.ee.spi.orbutil.logex.WrapperGenerator.access$300(WrapperGenerator.java:107)
at com.sun.corba.ee.spi.orbutil.logex.WrapperGenerator$2.invoke(WrapperGenerator.java:531)
at com.sun.corba.ee.spi.orbutil.proxy.CompositeInvocationHandlerImpl.invoke(CompositeInvocationHandlerImpl.java:99)
at $Proxy150.rfmAdapterActivatorFailed(Unknown Source)
at com.sun.corba.ee.impl.oa.rfm.ReferenceFactoryManagerImpl$AdapterActivatorImpl.unknown_adapter(ReferenceFactoryManagerImpl.java:172)
at com.sun.corba.ee.impl.oa.poa.POAImpl.find_POA(POAImpl.java:1039)
at com.sun.corba.ee.impl.oa.rfm.ReferenceFactoryManagerImpl.createReference(ReferenceFactoryManagerImpl.java:546)
at com.sun.corba.ee.impl.oa.rfm.ReferenceFactoryImpl.createReference(ReferenceFactoryImpl.java:62)
at org.glassfish.enterprise.iiop.impl.POARemoteReferenceFactory._createRef(POARemoteReferenceFactory.java:439)
at org.glassfish.enterprise.iiop.impl.POARemoteReferenceFactory.createRef(POARemoteReferenceFactory.java:402)
at org.glassfish.enterprise.iiop.impl.POARemoteReferenceFactory.createRemoteReference(POARemoteReferenceFactory.java:366)
at com.sun.ejb.containers.EntityContainer.getEJBObjectStub(EntityContainer.java:1819)
at com.sun.ejb.containers.EntityContainer.postFind(EntityContainer.java:920)
at com.sun.ejb.containers.EntityContainer.invokeFindByPrimaryKey(EntityContainer.java:815)
at com.sun.ejb.containers.EJBHomeInvocationHandler.invoke(EJBHomeInvocationHandler.java:306)
at $Proxy172.findByPrimaryKey(Unknown Source)
at sun.reflect.GeneratedMethodAccessor84.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.sun.corba.ee.impl.presentation.rmi.StubInvocationHandlerImpl.privateInvoke(StubInvocationHandlerImpl.java:241)
at com.sun.corba.ee.impl.presentation.rmi.StubInvocationHandlerImpl.invoke(StubInvocationHandlerImpl.java:152)
at com.sun.corba.ee.impl.presentation.rmi.codegen.CodegenStubBase.invoke(CodegenStubBase.java:227)
at trade._RegistryHome_DynamicStub.findByPrimaryKey(trade/_RegistryHome_DynamicStub.java)
at trade.TradeBean.findRegistry(TradeBean.java:692)
at trade.TradeBean.login(TradeBean.java:931)
at sun.reflect.GeneratedMethodAccessor81.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1052)
at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:1124)
at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:5367)
at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:619)
at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:801)
at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:571)
at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doAround(SystemInterceptorProxy.java:162)
at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:144)
at sun.reflect.GeneratedMethodAccessor78.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1052)
at org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:1124)
at com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:5367)
at com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:619)
at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:801)
at com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:571)
at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doAround(SystemInterceptorProxy.java:162)
at com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:144)
at sun.reflect.GeneratedMethodAccessor78.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:862)
at com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:801)
at com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:371)
at com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:5339)
at com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:5327)
at com.sun.ejb.containers.EJBObjectInvocationHandler.invoke(EJBObjectInvocationHandler.java:206)
at com.sun.ejb.containers.EJBObjectInvocationHandler.invoke(EJBObjectInvocationHandler.java:123)
at $Proxy175.login(Unknown Source)
at sun.reflect.GeneratedMethodAccessor72.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.sun.corba.ee.impl.presentation.rmi.StubInvocationHandlerImpl.privateInvoke(StubInvocationHandlerImpl.java:241)
at com.sun.corba.ee.impl.presentation.rmi.StubInvocationHandlerImpl.invoke(StubInvocationHandlerImpl.java:152)
at com.sun.corba.ee.impl.presentation.rmi.codegen.CodegenStubBase.invoke(CodegenStubBase.java:227)
at trade._Trade_DynamicStub.login(trade/_Trade_DynamicStub.java)
at trade.TradeAccessBean.login(TradeAccessBean.java:182)
at trade_client.TradeAction.doLogin(TradeAction.java:311)
at trade_client.TradeServletAction.doLogin(TradeServletAction.java:595)
at trade_client.TradeScenarioServlet.performTask(TradeScenarioServlet.java:224)
at trade_client.TradeScenarioServlet.doGet(TradeScenarioServlet.java:72)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:735)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1534)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:281)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:655)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:595)
at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:98)
at com.sun.enterprise.web.PESessionLockingStandardPipeline.invoke(PESessionLockingStandardPipeline.java:91)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:162)
at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:326)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:227)
at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:170)
at com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:817)
at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:718)
at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:1007)
at com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:225)
at com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137)
at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:104)
at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:90)
at com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:79)
at com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:54)
at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59)
at com.sun.grizzly.ContextTask.run(ContextTask.java:71)
at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532)
at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.omg.PortableServer.POAPackage.AdapterAlreadyExists: IDL:omg.org/PortableServer/POA/AdapterAlreadyExists:1.0
at com.sun.corba.ee.impl.oa.poa.POAImpl.create_POA(POAImpl.java:898)
at com.sun.corba.ee.impl.oa.rfm.ReferenceFactoryManagerImpl$AdapterActivatorImpl.unknown_adapter(ReferenceFactoryManagerImpl.java:158)
... 81 more

Comment by Ken Cavanaugh [ 06/Dec/10 ]

I think I just found the bug. It turns out that there are two small errors in the POAImpl.find_POA
method that combine to cause this problem:

  • I made an error in setting up the adaptorActivator call, such that the AA was called even when
    not needed. This caused the MOSTLY harmless errors in the server.log about the adapter already
    existing.
  • Unfortunately this error path leads to an error in unlocking: the code tries to unload the write lock
    when the read lock is held.

These two errors together result in the lost lock, leading to every subsequent call to find_POA waiting
to acquire a lock. I'm not entirely certain why there are so many threads hung waiting for the
readLock, but this certainly explains the writeLock wait problem.

Aside from fixing this, I'm also adding code to check that all locks are released at the end of find_POA,
and log a SEVERE error if they are not. There are 3 locks involved in this code:

  • parent POA read lock
  • parent POA write lock
  • child POA read lock

All 3 MUST be released at the end of find_POA.

Comment by Ken Cavanaugh [ 06/Dec/10 ]

orb.tgz is a gzipped tarball of the 8 ORB OSGi bundles.
Just copy the contents to the modules directory to test.

Comment by Stephen DiMilla [ 06/Dec/10 ]

latest jstack from first instance

Comment by Stephen DiMilla [ 06/Dec/10 ]

latest jstacks

Comment by Ken Cavanaugh [ 06/Dec/10 ]

Are the latest jstacks with the orb.tgz patch?
If so, I also need the server log file.

Comment by Joe Fialli [ 06/Dec/10 ]

Server logs produced with latest orb patch from this bug report.

Comment by Stephen DiMilla [ 06/Dec/10 ]

server logs with com.sun.corba.ee.ORBDebug=poa set. Since there are too many logs in the first instance, I will send private email with location of the logs. Attached are the logs from the second instance.

Comment by Ken Cavanaugh [ 08/Dec/10 ]

This is a second attempt at a patch for this issue. This is also
ORB version 3.1.0-b018, which will eventually be integrated into GF 3.1.
Changes:

  • Minor refactoring of find_POA
  • Added defensive code to recover from lost wakeup problems.

Please give this a try and see if it helps. If it does not,
I'll need server logs with ORBDebug set to "poa,subcontract"
and Jstacks. If possible, pointing to the time and the
corresponding log file(s) at which problems were first observed
would be very helpful: the last debug run resulted in 1.2 GB
of log files.

Comment by Ken Cavanaugh [ 09/Dec/10 ]

Fixed with ORB 3.1.0-b019 integration in GF svn rev 43637.

Generated at Wed Dec 07 13:50:56 UTC 2016 using JIRA 6.2.3#6260-sha1:63ef1d6dac3f4f4d7db4c1effd405ba38ccdc558.