[GLASSFISH-18272] [perf] Excessive lock contention during execution of trade2 in-memory replication benchmark with JRockit VM Created: 30/Jan/12  Updated: 03/Dec/12  Resolved: 31/Jan/12

Status: Closed
Project: glassfish
Component/s: performance
Affects Version/s: 3.1.2_b19
Fix Version/s: 3.1.2_b20

Type: Bug Priority: Major
Reporter: amitagarwal Assignee: Mahesh Kannan
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Tags: PSRBUG

 Description   

Trade2 in-memory replication benchmark with JRockit VM gives 90% lower throughput than Sun Hotspot VM. Thread dump shows contention in following code-path,

"http-thread-pool-8080(4)" id=142 idx=0x220 tid=32438 prio=5 alive, blocked, native_blocked, daemon
– Blocked trying to get lock: java/util/HashMap@0x100903bb8[unlocked]
at jrockit/vm/Threads.yield()V(Native Method)
at jrockit/vm/Locks.fatLockBlockOrSpin(Locks.java:1386)
at jrockit/vm/Locks.lockFat(Locks.java:1512)[optimized]
at jrockit/vm/Locks.monitorEnterSecondStageHard(Locks.java:1054)[optimized]
at jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1005)[optimized]
at java/lang/reflect/Proxy.getProxyClass(Proxy.java:417)[optimized]
at java/lang/reflect/Proxy.newProxyInstance(Proxy.java:581)[optimized]
at sun/reflect/annotation/AnnotationParser.annotationForMap(AnnotationParser.java:239)[inlined]
at sun/reflect/annotation/AnnotationParser.parseAnnotation(AnnotationParser.java:229)[inlined]
at sun/reflect/annotation/AnnotationParser.parseAnnotations2(AnnotationParser.java:69)[inlined]
at sun/reflect/annotation/AnnotationParser.parseAnnotations(AnnotationParser.java:52)[optimized]
at java/lang/reflect/Field.declaredAnnotations(Field.java:1014)[inlined]
at java/lang/reflect/Field.getAnnotation(Field.java:1000)[inlined]
at org/jvnet/hk2/component/InjectionManager.inject(InjectionManager.java:137)[optimized]
^-- Holding lock: java/lang/reflect/Field@0x130c6bd90[biased lock]
at org/jvnet/hk2/component/InjectionManager.inject(InjectionManager.java:93)[inlined]
at com/sun/hk2/component/AbstractCreatorImpl.inject(AbstractCreatorImpl.java:126)[inlined]
at com/sun/hk2/component/ConstructorCreator.initialize(ConstructorCreator.java:91)[optimized]
at com/sun/hk2/component/AbstractCreatorImpl.get(AbstractCreatorImpl.java:82)[optimized]
at com/sun/hk2/component/EventPublishingInhabitant.get(EventPublishingInhabitant.java:139)[optimized]
at com/sun/hk2/component/AbstractInhabitantImpl.get(AbstractInhabitantImpl.java:78)[optimized]
at org/jvnet/hk2/component/Habitat.getBy(Habitat.java:1056)[inlined]
at org/jvnet/hk2/component/Habitat.getByType(Habitat.java:1037)[inlined]
at org/jvnet/hk2/component/Habitat.getComponent(Habitat.java:781)[optimized]
at com/sun/ejb/containers/ContainerSynchronization.registerForTxCheckpoint(ContainerSynchronization.java:244)
at com/sun/ejb/containers/StatefulSessionContainer.afterBegin(StatefulSessionContainer.java:1805)
at com/sun/ejb/containers/BaseContainer.startNewTx(BaseContainer.java:4692)[optimized]
at com/sun/ejb/containers/BaseContainer.preInvokeTx(BaseContainer.java:4597)[optimized]
at com/sun/ejb/containers/BaseContainer.preInvoke(BaseContainer.java:1914)[optimized]
at com/sun/ejb/containers/EJBObjectInvocationHandler.invoke(EJBObjectInvocationHandler.java:205)[inlined]
at com/sun/ejb/containers/EJBObjectInvocationHandler.invoke(EJBObjectInvocationHandler.java:123)[optimized]
at $Proxy190.displayProperties()V(Unknown Source)[optimized]
at sun/reflect/GeneratedMethodAccessor104.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;(Unknown Source)[optimized]
at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)[optimized]
at java/lang/reflect/Method.invoke(Method.java:597)[optimized]
at com/sun/corba/ee/impl/presentation/rmi/StubInvocationHandlerImpl.privateInvoke(StubInvocationHandlerImpl.java:241)[inlined]
at com/sun/corba/ee/impl/presentation/rmi/StubInvocationHandlerImpl.invoke(StubInvocationHandlerImpl.java:152)[optimized]
at com/sun/corba/ee/impl/presentation/rmi/codegen/CodegenStubBase.invoke(CodegenStubBase.java:227)[inlined]
at trade/_MySession_DynamicStub.displayProperties()V(trade/_MySession_DynamicStub.java)[optimized]
at trade_client/TradeServletAction.doPingSFSBSession(TradeServletAction.java:58)[optimized]
at trade_client/TradeServletAction.doPortfolio(TradeServletAction.java:966)[optimized]
at trade_client/TradeServletAction.doBuy(TradeServletAction.java:447)
at trade_client/TradeScenarioServlet.performTask(TradeScenarioServlet.java:307)[inlined]
at trade_client/TradeScenarioServlet.doGet(TradeScenarioServlet.java:72)[optimized]
at javax/servlet/http/HttpServlet.service(HttpServlet.java:668)[optimized]
at javax/servlet/http/HttpServlet.service(HttpServlet.java:770)[optimized]
at org/apache/catalina/core/StandardWrapper.service(StandardWrapper.java:1542)[inlined]
at org/apache/catalina/core/StandardWrapperValve.invoke(StandardWrapperValve.java:281)[optimized]
at org/apache/catalina/core/StandardContextValve.invoke(StandardContextValve.java:175)[optimized]
at org/apache/catalina/core/StandardPipeline.doInvoke(StandardPipeline.java:655)[inlined]
at org/apache/catalina/core/StandardPipeline.invoke(StandardPipeline.java:595)[optimized]
at org/apache/catalina/core/StandardHostValve.invoke(StandardHostValve.java:161)[optimized]
at org/apache/catalina/connector/CoyoteAdapter.doService(CoyoteAdapter.java:331)[optimized]
at org/apache/catalina/connector/CoyoteAdapter.service(CoyoteAdapter.java:231)[optimized]
at com/sun/enterprise/v3/services/impl/ContainerMapper.service(ContainerMapper.java:174)[optimized]
at com/sun/grizzly/http/ProcessorTask.invokeAdapter(ProcessorTask.java:849)[optimized]
at com/sun/grizzly/http/ProcessorTask.doProcess(ProcessorTask.java:746)[optimized]
at com/sun/grizzly/http/ProcessorTask.process(ProcessorTask.java:1045)[inlined]
at com/sun/grizzly/http/DefaultProtocolFilter.execute(DefaultProtocolFilter.java:228)[optimized]
at com/sun/grizzly/DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137)[inlined]
at com/sun/grizzly/DefaultProtocolChain.execute(DefaultProtocolChain.java:104)[inlined]
at com/sun/grizzly/DefaultProtocolChain.execute(DefaultProtocolChain.java:90)[inlined]
at com/sun/grizzly/http/HttpProtocolChain.execute(HttpProtocolChain.java:79)[optimized]
at com/sun/grizzly/ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:54)[optimized]
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)
at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)



 Comments   
Comment by amitagarwal [ 30/Jan/12 ]

Tried a patch provided by Scott, this resolves the contention and throughput improved significantly (from 800 ops/sec to over 8000 ops/sec).

Comment by Mahesh Kannan [ 31/Jan/12 ]

svn commit -m "Fix for 18272. Tested by Amit. Reviewed by Marina. QL & EJB devtests passed"
Sending ejb-container/src/main/java/com/sun/ejb/containers/ContainerSynchronization.java
Sending ejb-container/src/main/java/com/sun/ejb/containers/StatefulSessionContainer.java
Sending ejb-container/src/main/java/com/sun/ejb/containers/builder/StatefulContainerBuilder.java
Transmitting file data ...
Committed revision 52348.

Approved by: Joe Di Pol

What is the impact on the customer of the bug?
Slow performance when running ejb apps with SFSBs in a tx

What is the cost/risk of fixing the bug?
Not much. Touched three files

Is there an impact on documentation or message strings?
Not for documentation.

Which tests should QA (re)run to verify the fix did not destabilize GlassFish?
We need to run ha QA tests

Which is the targeted build of 3.1.2 for this fix?
3_1_2_b20

Generated at Sat Mar 07 01:14:47 UTC 2015 using JIRA 6.2.3#6260-sha1:63ef1d6dac3f4f4d7db4c1effd405ba38ccdc558.