Duplicate request threads are received at JBoss during Load Testing only for some value of maxThreads

[rupesh.bhadeshiya]

Hi.

(1) We are getting Duplicate http requests / threads in JBoss when carrying out Load Testing for below configuration/details:

Concurrent Load Test Requests Sent:

- 100 (i.e. 100 concurrent users/threads)

- Software Used is: Grinder tool

App Server: JBoss:

- version: 5.1.0.GA AS, Non clustered

- maxThreads: default (which is 200)

- Xmx = Xmx = 1024m (Total System RAM is 2GB)

- Database Connection Pool: Min=50, Max=100

Database: MySQL:

  - version: 5.0.40 Enterprise Server (GPL)

Our Application Consists of:

  - an ear comprising:

   - a web application having an MVC framework (webwork)

- several EJB applications as needed by web application

Exception we are getting:

17:33:20,224 ERROR [JDBCExceptionReporter] Duplicate entry '1011287747835421-DEFAULT_USER' for key 2

17:33:20,249 ERROR [AbstractFlushingEventListener] Could not synchronize database state with session

org.hibernate.exception.ConstraintViolationException: Could not execute JDBC batch update

at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:71)

at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)

at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:249)

at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:235)

at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:139)

at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)

at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)

at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)

at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)

at org.hibernate.transaction.CacheSynchronization.beforeCompletion(CacheSynchronization.java:59)

at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:101)

at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:269)

at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:89)

at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)

at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1423)

at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:137)

at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)

at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:162)

at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1028)

at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:732)

at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:701)

at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:321)

at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:116)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)

at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:635)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at com.opensymphony.xwork.DefaultActionInvocation.invokeAction(DefaultActionInvocation.java:300)

at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:166)

at com.opensymphony.xwork.interceptor.AroundInterceptor.intercept(AroundInterceptor.java:35)

at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:164)

at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:164)

at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:164)

at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:164)

at com.opensymphony.xwork.DefaultActionProxy.execute(DefaultActionProxy.java:116)

at com.opensymphony.webwork.dispatcher.ServletDispatcher.serviceAction(ServletDispatcher.java:272)

at com.opensymphony.webwork.dispatcher.ServletDispatcher.service(ServletDispatcher.java:237)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)

at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)

at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190)

at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92)

at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)

at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)

at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)

at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)

at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)

at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)

at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)

at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)

at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)

at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)

at java.lang.Thread.run(Thread.java:662)

Caused by: java.sql.BatchUpdateException: Duplicate entry '1011287747835421-DEFAULT_USER' for key 2

at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2007)

at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1443)

at org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:774)

at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:48)

at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:242)

... 62 more

We have found that we have a user record created in database on server side with the said id (1011287747835421). Hence it is clear that there was another thread trying to create user record with same id and hence failing. We also found that in this case, there is one request from Load Testing client that was not served by server. We matched both the requests we sent from Load Testing client and those for which server processed them and found that in each such (Duplicate entry exception) case, our web application could receive one request less than total request sent by Load Testing client.

(2) We also found that when we are incresing the maxThreads count to more value such as 500 or 700, we no more get the Duplicate request issue.

Can you please guide us what can be the issue?

Thanks in advance for any help on this matter.

Thanks & Best Regards,

Rupesh

Hi.

(1) We are getting Duplicate http requests / threads in JBoss when carrying out Load Testing for below configuration/details:

Concurrent Load Test Requests Sent:

- 100 (i.e. 100 concurrent users/threads)

- Software Used is: Grinder tool

App Server: JBoss:

- version: 5.1.0.GA AS, Non clustered

- maxThreads: default (which is 200)

- Xmx = Xmx = 1024m (Total System RAM is 2GB)

- Database Connection Pool: Min=50, Max=100

Database: MySQL:

  - version: 5.0.40 Enterprise Server (GPL)

Our Application Consists of:

  - an ear comprising:

   - a web application having an MVC framework (webwork)

- several EJB applications as needed by web application

Exception we are getting:

17:33:20,224 ERROR [JDBCExceptionReporter] Duplicate entry '1011287747835421-DEFAULT_USER' for key 2

17:33:20,249 ERROR [AbstractFlushingEventListener] Could not synchronize database state with session

org.hibernate.exception.ConstraintViolationException: Could not execute JDBC batch update

at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:71)

at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)

at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:249)

at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:235)

at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:139)

at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)

at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)

at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)

at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)

at org.hibernate.transaction.CacheSynchronization.beforeCompletion(CacheSynchronization.java:59)

at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:101)

at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:269)

at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:89)

at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)

at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1423)

at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:137)

at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)

at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:162)

at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1028)

at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:732)

at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:701)

at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:321)

at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:116)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)

at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:635)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at com.opensymphony.xwork.DefaultActionInvocation.invokeAction(DefaultActionInvocation.java:300)

at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:166)

at com.opensymphony.xwork.interceptor.AroundInterceptor.intercept(AroundInterceptor.java:35)

at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:164)

at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:164)

at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:164)

at com.opensymphony.xwork.DefaultActionInvocation.invoke(DefaultActionInvocation.java:164)

at com.opensymphony.xwork.DefaultActionProxy.execute(DefaultActionProxy.java:116)

at com.opensymphony.webwork.dispatcher.ServletDispatcher.serviceAction(ServletDispatcher.java:272)

at com.opensymphony.webwork.dispatcher.ServletDispatcher.service(ServletDispatcher.java:237)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)

at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)

at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190)

at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92)

at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)

at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)

at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)

at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)

at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)

at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)

at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)

at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)

at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)

at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)

at java.lang.Thread.run(Thread.java:662)

Caused by: java.sql.BatchUpdateException: Duplicate entry '1011287747835421-DEFAULT_USER' for key 2

at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2007)

at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1443)

at org.jboss.resource.adapter.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:774)

at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:48)

at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:242)

... 62 more

We have found that we have a user record created in database on server side with the said id (1011287747835421). Hence it is clear that there was another thread trying to create user record with same id and hence failing. We also found that in this case, there is one request from Load Testing client that was not served by server. We matched both the requests we sent from Load Testing client and those for which server processed them and found that in each such (Duplicate entry exception) case, our web application could receive one request less than total request sent by Load Testing client.

(2) We also found that when we are incresing the maxThreads count to more value such as 500 or 700, we no more get the Duplicate request issue.

Can you please guide us what can be the issue?

Thanks in advance for any help on this matter.

Thanks & Best Regards,

Rupesh

[wdfink]

Is it during entity creation?

Could it be that the id generation is the problem?

[rupesh.bhadeshiya]

Thanks for your reply.

No the ID is also sent as the part of request from Load Testing client and is not generated on server, which means there is no scope for duplicate ID generation. Can it be possible that the server internally queues the requests and while flushing the queue it might be resending same request multiple times.

Thanks again for your attention to the post.

Thanks and Best Regards,

Rupesh

[wdfink]

Ok,

you talk about HTTP requests. In this case the request is finished with sending the result, all transactions and entities should be persistent (exept if you use statefull session with extended persistence context).

For me it sounds like a concurrency problem when generating the id, have you checked the load testing whether the id is duplicated here because of multithreading and the requests are send twice?

[rupesh.bhadeshiya]

Thanks for your reply and input.

Actually we do not generate load test entity IDs on the fly, we generate it offline. The database itself is having unique constrains where we generate and store these IDs hence there is not possibility to have duplicate IDs being generated. Also based on your input we have verified each request being sent from load testing client are having unique IDs only, without any repetitive IDs. At the same time we have also verified that Load Testing client do not repeat any request which may lead to the exceptional scenario. The first entry point of request within application has logs enabled where we have identified the duplicate request which is leading the exceptional scenarios.

Thanks and Best Regards,

Rupesh

[rupesh.bhadeshiya]

HI.

We have got solution to this issue. The problem was within application: A spring bean was the cause of the issue: This spring beab was responsible for extracting data from HTTP request and forming application specific request and putting it in HttpSession (from which other business objects would take it and use it). It was declared as singleton="true" hence its only one instance would be created and shared by all the threads entering in the code. As soon as we changed its configuration to singleton="false" and in code wherever using it, always look up it from Spring bean context (and hence each time get a new instance of it), this issue got resolved.

But to come to this conclusion, we took a lot of logs : Logs at Load-Testing client (Grinder in our case) - to know if it is sending duplicate requests, then took logs at Apache Load Balancer level (to know whether duplicate requests are reaching at its level), then at JBoss level (accessor logs) to know if there also duplicate requests are reaching, and then took logs at various classes at application level (in order of they receving request and processing it: Web Filter, WebWork based our interceptors, and then to finally action class). There we come to know that no duplicate requests were received upto a particular interceptor's intercept() method entry and duplicates were noted at exit of that method ... and further micro analysis revealed the above said spring bean.

I thought posting answer to this issue might also help other people.

Thanks a lot to all for all help.

Thanks & BR,

Rupesh

[wdfink]

Thanks Rupesh for your final clarification.