Greetings JBoss/Jetty gurus...

In the process of evaluating and testing JBoss (3.0.2 + Jetty), I have run into a problem that I'm hoping someone will be able to shed some light on.

Basically we're experiencing severe performance degradation when we have more than one user accessing an app. I've trimmed the application down to a test with a single servlet which, when invoked, calls a single method (Transaction Required) on a stateless session ejb. The session bean method simply invokes findByPrimaryKey on a CMP2.0 (Local) Entity EJB, then calls a simple attribute accessor (public abstract String getName() - also Tx Required) on the returned entity. The DataSource for the Entity is a MSSQLServer database, and we are using the Microsoft JDBC driver. I've setup a load tester (Mercury LoadRunner) to hit this servlet and let it rip.

With a single virtual user the app performs very well, we get an average response time of 21ms and can execute thousands of page hits per minute. If I increase the number of virtual users to 2 the invokations will periodically (approx 15 second interval) hang for about 6 seconds. When the users are increased to 3 the hangs last 12 seconds, with 4 users the hangs last 18 seconds, etc... These hangs seem to occur when mutliple threads/transactions are attempting to load and access the same entity at the same time.

From the (purchased) documentation I would expect access to the single instance of the entity to be serialized (using "Standard CMP 2.x Entity Bean" configuration), but I would not expect the arbitrarily long delays. I tried switching to the "Instance per Transaction" configuration, but saw the same results. A check of the jboss log (with TRACE enabled) is (hopefully) attached. The log shows delays occuring at 17:06:02 (5 second delay) and 17:06:07 (6 second delay), but doesn't give any indication (at least to me) as to what may be causing the hang (and more importantly, the eventual release).

After adding a bunch more debug output it appears fairly obvious (to me) that the delays are occuring within/because-of the QueuedPessimisticEJBLock (BeanLockSupport) sync method, but I haven't been able to track down why they are occuring (again, I understand that access should be serialized, I don't understand why the 5 second delays are occuring). As far as I'm able to determine this is *not* a deadlock issue, and I've verified that the delay is not occuring due to the database.

If I remove Jetty and the servlet from the picture by creating a standalone test client which spawns 10 threads that each perform the lookup/findByPrimaryKey/getName sequence 1000 times, the problem does not occur. With 10 threads looping 1000 times I'm getting average cycle-times of 84ms (with no iteration, except the very first Home lookup, taking more than 5 seconds).

I've been pulling my hair out all week on this problem, if anyone has a suggestion where to look to try to resolve this, I would be much appreciative.

Thanks in advance,
Ralph Roland

PS: Apparently the forum is not allowing me to attach the log file snippet... so, I'm going to include just a very small sample here:

2002-09-05 17:06:02,437 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] TX_REQUIRED for getName
2002-09-05 17:06:02,437 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] Thread came in with tx TransactionImpl:XidImpl [FormatId=257, GlobalId=host0021//27, BranchQual=]
2002-09-05 17:06:02,437 TRACE [org.jboss.ejb.plugins.EntityLockInterceptor] Begin invoke, key=class com.strataj.petshop.module.catalog.ejb.entity.product.ProductPK=>1
2002-09-05 17:06:07,937 TRACE [org.jboss.ejb.plugins.EntityLockInterceptor] End invoke, key=class com.strataj.petshop.module.catalog.ejb.entity.product.ProductPK=>1
2002-09-05 17:06:07,937 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] TxInterceptorCMT: In finally
2002-09-05 17:06:07,937 TRACE [org.jboss.ejb.plugins.LogInterceptor] End method=getName
2002-09-05 17:06:07,937 TRACE [org.jboss.ejb.plugins.StatelessSessionInstancePool] 100 Free instance:org.jboss.ejb.plugins.StatelessSessionInstancePool@5a4a77#null#TransactionImpl:XidImpl [FormatId=257, GlobalId=host0021//24, BranchQual=]#true#class com.strataj.petshop.module.catalog.ejb.session.catalogmanager.CatalogManagerBean
2002-09-05 17:06:07,937 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] TxInterceptorCMT: In finally
2002-09-05 17:06:07,937 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] TxInterceptorCMT:before commit of TransactionImpl:XidImpl [FormatId=257, GlobalId=host0021//24, BranchQual=]
2002-09-05 17:06:07,937 TRACE [org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreEntityCommand.Product] Store command NOT executed. Entity is not dirty: pk=class com.strataj.petshop.module.catalog.ejb.entity.product.ProductPK=>1
2002-09-05 17:06:13,609 TRACE [org.jboss.ejb.plugins.EntitySynchronizationInterceptor] afterCompletion, clear tx for ctx=org.jboss.ejb.EntityEnterpriseContext@7e479a, tx=TransactionImpl:XidImpl [FormatId=257, GlobalId=host0021//24, BranchQual=]
2002-09-05 17:06:13,609 TRACE [org.jboss.ejb.plugins.EntitySynchronizationInterceptor] afterCompletion, sent notify on TxLock for ctx=org.jboss.ejb.EntityEnterpriseContext@7e479a
2002-09-05 17:06:13,734 TRACE [org.jboss.ejb.plugins.TxInterceptorCMT] TxInterceptorCMT:after commit of TransactionImpl:XidImpl [FormatId=257, GlobalId=host0021//24, BranchQual=]