1 Reply Latest reply on Jun 27, 2013 4:52 AM by kalaiselvamp

EJB3 is slow when invoke with new transaction

kalaiselvamp Feb 26, 2013 7:10 PM

Hi,

We have EJB(EJB3.0) application which is deployed on JBoss 5.0, we feel sometimes(when invoke with new transaction) EJB takes long time to return the data(data volume is always same) to invoker.

@Stateless(name = "RequiresNewSessionBean")

@RemoteBinding (jndiBinding = "N_All/RequiresNewSessionBean/remote")

@LocalBinding (jndiBinding = "N_All/RequiresNewSessionBean/local")

@TransactionManagement(TransactionManagementType.CONTAINER)

@TransactionAttribute(TransactionAttributeType.REQUIRES_NEW)

com.test.ejb.RequiresNewSessionBean

com.test.ejb.LocalSessionBeanInvoker (this class has only invoking parts) will invoke "com.test.ejb.RequiresNewSessionBean"

As you see the below 3 scenarios, execution of "com.test.ejb.RequiresNewSessionBean" has been finished but it takes time to return to invoker.

The time taken is changing from "8 ms" to maximum "150 ms" in my local system.

But in our production server this time taken is went up to "3000 ms" (only sometimes not all the times, by default it will be within 1 ~ 2 ms in Production server)

Please share your suggestions to overcome this issue.

Scenario 1

----------

17:02:15,052 DEBUG [LocalSessionBeanInvoker] 20130225-080213979 0001 com.test.ejb.LocalSessionBeanInvoker has started.20130225080215052

17:02:15,054 DEBUG [RequiresNewSessionBean] 20130225-080213979 0001 com.test.ejb.RequiresNewSessionBean has started.20130225080215053

17:02:15,094 DEBUG [RequiresNewSessionBean] 20130225-080213979 0001 com.test.ejb.RequiresNewSessionBean has finished.20130225080215093

17:02:15,094 DEBUG [RequiresNewSessionBean] 20130225-080213979 0001 [com.test.ejb.RequiresNewSessionBean]Elapsed time is 41 ms.

17:02:15,101 DEBUG [LocalSessionBeanInvoker] 20130225-080213979 0001 com.test.ejb.LocalSessionBeanInvoker has finished.20130225080215101

17:02:15,101 DEBUG [LocalSessionBeanInvoker] 20130225-080213979 0001 [com.test.ejb.LocalSessionBeanInvoker]Elapsed time is 49 ms.

Scenario 2

----------

17:11:35,343 DEBUG [LocalSessionBeanInvoker] 20130225-081135291 0001 com.test.ejb.LocalSessionBeanInvoker has started.20130225081135343

17:11:35,344 DEBUG [RequiresNewSessionBean] 20130225-081135291 0001 com.test.ejb.RequiresNewSessionBean has started.20130225081135344

17:11:35,402 DEBUG [RequiresNewSessionBean] 20130225-081135291 0001 com.test.ejb.RequiresNewSessionBean has finished.20130225081135402

17:11:35,402 DEBUG [RequiresNewSessionBean] 20130225-081135291 0001 [com.test.ejb.RequiresNewSessionBean]Elapsed time is 53 ms.

17:11:35,417 DEBUG [LocalSessionBeanInvoker] 20130225-081135291 0001 com.test.ejb.LocalSessionBeanInvoker has finished.20130225081135417

17:11:35,417 DEBUG [LocalSessionBeanInvoker] 20130225-081135291 0001 [com.test.ejb.LocalSessionBeanInvoker]Elapsed time is 71 ms.

Scenario 3

----------

17:32:25,705 DEBUG [LocalSessionBeanInvoker] 20130225-083225641 0001 com.test.ejb.LocalSessionBeanInvoker has started.20130225083225705

17:32:25,708 DEBUG [RequiresNewSessionBean] 20130225-083225641 0001 com.test.ejb.RequiresNewSessionBean has started.20130225083225708

17:32:25,775 DEBUG [RequiresNewSessionBean] 20130225-083225641 0001 com.test.ejb.RequiresNewSessionBean has finished.20130225083225775

17:32:25,775 DEBUG [RequiresNewSessionBean] 20130225-083225641 0001 [com.test.ejb.RequiresNewSessionBean]Elapsed time is 67 ms.

17:32:25,789 DEBUG [LocalSessionBeanInvoker] 20130225-083225641 0001 com.test.ejb.LocalSessionBeanInvoker has finished.20130225083225789

17:32:25,789 DEBUG [LocalSessionBeanInvoker] 20130225-083225641 0001 [com.test.ejb.LocalSessionBeanInvoker]Elapsed time is 84 ms.

1. Re: EJB3 is slow when invoke with new transaction

kalaiselvamp Jun 27, 2013 4:52 AM (in response to kalaiselvamp)

Time was taken when commit the transaction. (may due to heavy load in DB server)

2013-06-06 01:48:17,919 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (http-10.32.131.25-80-13) BasicAction::End() for action-id a208319:d48e:51aeeaba:1a03
2013-06-06 01:48:17,919 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (http-10.32.131.25-80-13) BasicAction::onePhaseCommit() for action-id a208319:d48e:51aeeaba:1a03
2013-06-06 01:48:17,919 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (http-10.32.131.25-80-13) LastResourceRecord::topLevelPrepare() for 0:0:0:1
2013-06-06 01:48:18,686 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (http-10.32.131.25-80-13) LastResourceRecord::topLevelCommit() for 0:0:0:1

http://anonsvn.jboss.org/repos/labs/labs/jbosstm/tags/JBOSSTS_4_6_1_GA_CP04/ArjunaCore/arjuna/classes/com/arjuna/ats/arjuna/LastResourceRecord.java

151 public int topLevelCommit ()
152 {
153 if (tsLogger.arjLogger.debugAllowed())
154 {
155 tsLogger.arjLogger.debug(DebugLevel.FUNCTIONS, VisibilityLevel.VIS_PUBLIC, FacilityCode.FAC_ABSTRACT_REC, "LastResourceRecord::topLevelCommit() for "
156           + order());
157 }
158
159 return TwoPhaseOutcome.FINISH_OK;
160 }
161
162 public int topLevelPrepare ()
163 {
164 if (tsLogger.arjLogger.debugAllowed())
165 {
166 tsLogger.arjLogger.debug(DebugLevel.FUNCTIONS, VisibilityLevel.VIS_PUBLIC, FacilityCode.FAC_ABSTRACT_REC, "LastResourceRecord::topLevelPrepare() for "
167           + order());
168 }
169
170 if ((_lro != null) && (_lro.commit() == TwoPhaseOutcome.FINISH_OK))
171 {
172 return TwoPhaseOutcome.PREPARE_OK;
173 }
174 else
175 return TwoPhaseOutcome.PREPARE_NOTOK;
176   }

1 of 1 people found this helpful
Actions