tomee-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Romain Manni-Bucau <rmannibu...@gmail.com>
Subject Re: JTA Commit Timing
Date Wed, 26 Apr 2017 15:12:15 GMT
maybe switch to dbcp pool to see if it behaves the same, if not can be an
equals/hashcode issue


Romain Manni-Bucau
@rmannibucau <https://twitter.com/rmannibucau> |  Blog
<https://blog-rmannibucau.rhcloud.com> | Old Blog
<http://rmannibucau.wordpress.com> | Github <https://github.com/rmannibucau> |
LinkedIn <https://www.linkedin.com/in/rmannibucau> | JavaEE Factory
<https://javaeefactory-rmannibucau.rhcloud.com>

2017-04-26 16:45 GMT+02:00 Paul Carter-Brown <
paul.carter-brown@smilecoms.com>:

> Hi Romain,
>
> In order to better understand the commit timing, I have put some logging in
> a custom MySQL ConnectionLifecycleInterceptor so that I can do a stack
> trace when commit is called and see where it's called relative to the SOAP
> service invocation. I also put a Thread.sleep(1000) in the commit method of
> my ConnectionLifecycleInterceptor to see how it influenced the response
> going back to the client. Whats very strange is that the 1000ms sleep does
> result in the response taking almost 1000ms longer. I say almost, because
> again when running with multiple threads, I can get a situation where the
> response beats the completion of the commit. I cannot create this when the
> client has only one thread. Here is a log snippet showing the scenario:
>
> 1) Here is our ConnectionLifecycleInterceptor getting the commit call and
> logging the stack before sleeping for 1000ms. Its committing a new row with
> ID 615867
> 2017/04/26 16:22:50.592 FINE
>  [TomEE-Exec-15][207][com.smilecoms.commons.base.lifecycle.
> SmileConnectionLifecycleInterceptor.commit]
> |Commit called
> 2017/04/26 16:22:50.593 FINE
>  [TomEE-Exec-15][207][com.smilecoms.commons.base.lifecycle.
> SmileConnectionLifecycleInterceptor.commit]
> |Stack in commit. Sleeping now:
> java.lang.Exception
>         at
> com.smilecoms.commons.base.lifecycle.SmileConnectionLifecycleInterc
> eptor.commit(SmileConnectionLifecycleInterceptor.java:32)
>         at com.mysql.jdbc.ConnectionImpl$2.forEach(ConnectionImpl.java:
> 1593)
>         at com.mysql.jdbc.ConnectionImpl$2.forEach(ConnectionImpl.java:
> 1592)
>         at com.mysql.jdbc.IterateBlock.doForAll(IterateBlock.java:61)
>         at com.mysql.jdbc.ConnectionImpl.commit(ConnectionImpl.java:1599)
>         at sun.reflect.GeneratedMethodAccessor137.invoke(Unknown Source)
>         at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(
> DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:498)
>         at
> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(
> ProxyConnection.java:126)
>         at
> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(
> JdbcInterceptor.java:108)
>         at
> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(
> DisposableConnectionFacade.java:81)
>         at com.sun.proxy.$Proxy58.commit(Unknown Source)
>         at
> org.apache.openejb.resource.jdbc.managed.local.LocalXAResource.commit(
> LocalXAResource.java:131)
>         at
> org.apache.geronimo.transaction.manager.TransactionImpl.commitResource(
> TransactionImpl.java:627)
>         at
> org.apache.geronimo.transaction.manager.TransactionImpl.commit(
> TransactionImpl.java:305)
>         at
> org.apache.geronimo.transaction.manager.TransactionManagerImpl.commit(
> TransactionManagerImpl.java:252)
>         at
> org.apache.openejb.core.transaction.JtaTransactionPolicy.
> completeTransaction(JtaTransactionPolicy.java:331)
>         at
> org.apache.openejb.core.transaction.TxRequired.commit(TxRequired.java:76)
>         at
> org.apache.openejb.core.transaction.EjbTransactionUtil.afterInvoke(
> EjbTransactionUtil.java:77)
>         at
> org.apache.openejb.core.stateless.StatelessContainer._
> invoke(StatelessContainer.java:271)
>         at
> org.apache.openejb.core.stateless.StatelessContainer.
> invoke(StatelessContainer.java:212)
>         at
> org.apache.openejb.server.cxf.ejb.EjbMethodInvoker.
> preEjbInvoke(EjbMethodInvoker.java:125)
>         at
> org.apache.openejb.server.cxf.ejb.EjbMethodInvoker.invoke(
> EjbMethodInvoker.java:82)
>         at
> org.apache.cxf.service.invoker.AbstractInvoker.
> invoke(AbstractInvoker.java:74)
>         at
> org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.
> run(ServiceInvokerInterceptor.java:59)
>         at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
>         at java.util.concurrent.FutureTask.run(FutureTask.java:266)
>         at
> org.apache.cxf.interceptor.ServiceInvokerInterceptor$2.
> run(ServiceInvokerInterceptor.java:126)
>         at
> org.apache.cxf.workqueue.SynchronousExecutor.execute(
> SynchronousExecutor.java:37)
>         at
> org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(
> ServiceInvokerInterceptor.java:131)
>         at
> org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(
> PhaseInterceptorChain.java:308)
>         at
> org.apache.cxf.transport.ChainInitiationObserver.onMessage(
> ChainInitiationObserver.java:121)
>         at
> org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(
> AbstractHTTPDestination.java:262)
>         at
> org.apache.openejb.server.cxf.CxfWsContainer.onMessage(
> CxfWsContainer.java:85)
>         at
> org.apache.openejb.server.webservices.WsServlet.service(WsServlet.java:98)
>         at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(
> ApplicationFilterChain.java:230)
>         at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(
> ApplicationFilterChain.java:165)
>         at
> org.apache.catalina.core.StandardWrapperValve.invoke(
> StandardWrapperValve.java:198)
>         at
> org.apache.catalina.core.StandardContextValve.invoke(
> StandardContextValve.java:96)
>         at
> org.apache.catalina.core.StandardHostValve.invoke(
> StandardHostValve.java:140)
>         at
> org.apache.catalina.valves.ErrorReportValve.invoke(
> ErrorReportValve.java:79)
>         at
> org.apache.tomee.catalina.OpenEJBSecurityListener$RequestCapturer.invoke(
> OpenEJBSecurityListener.java:97)
>         at
> org.apache.catalina.core.StandardEngineValve.invoke(
> StandardEngineValve.java:87)
>         at
> org.apache.catalina.connector.CoyoteAdapter.service(
> CoyoteAdapter.java:349)
>         at
> org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:783)
>         at
> org.apache.coyote.AbstractProcessorLight.process(
> AbstractProcessorLight.java:66)
>         at
> org.apache.coyote.AbstractProtocol$ConnectionHandler.process(
> AbstractProtocol.java:798)
>         at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.
> doRun(NioEndpoint.java:1434)
>         at
> org.apache.tomcat.util.net.SocketProcessorBase.run(
> SocketProcessorBase.java:49)
>         at
> java.util.concurrent.ThreadPoolExecutor.runWorker(
> ThreadPoolExecutor.java:1142)
>         at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(
> ThreadPoolExecutor.java:617)
>         at
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(
> TaskThread.java:61)
>         at java.lang.Thread.run(Thread.java:745)
>
> 2) Now here is the clients request being processed in our EJB looking for
> the row that was created above but is not finished committing yet. The row
> with ID 615867 is not found.
> 2017/04/26 16:22:51.588 FINE
>  [TomEE-Exec-10][202][com.smilecoms.im.IdentityManager.getCustomers]
> |Looking up a single customer with ID [615867]
> 3) Here is the sleep having finished.
> 2017/04/26 16:22:51.594 FINE
>  [TomEE-Exec-15][207][com.smilecoms.commons.base.lifecycle.
> SmileConnectionLifecycleInterceptor.commit]
> |Commit sleep finished
>
> I would expect that only after 2017/04/26 16:22:51.594 would the client
> receive the SOAP response to the insert but clearly that is not the case.
> It is slowed down by the sleep but there still seems to be some race
> condition where it somehow can still beat the commit returning. If the
> commit were called after sending the response or in parallel to doing so
> then I would have expected the 1000ms sleep to not impact the response time
> of the service. Very very strange....
>
> Here is the code snippet of my SmileConnectionLifecycleInterceptor:
>
> public class SmileConnectionLifecycleInterceptor implements
> ConnectionLifecycleInterceptor {
>
>     private static final Logger log =
> LoggerFactory.getLogger(SmileConnectionLifecycleInterceptor.class);
>
>
>     @Override
>     public boolean commit() throws SQLException {
>         log.debug("Commit called");
>         log.debug("Stack in commit. Sleeping now: ", new Exception());
>         try {
>             Thread.sleep(1000);
>         } catch (Exception e) {
>
>         }
>         log.debug("Commit sleep finished");
>         return true;
>     }
> ...
>
>
> Any thoughts?
>
> Paul
>
> On 26 April 2017 at 13:50, Paul Carter-Brown <
> paul.carter-brown@smilecoms.com> wrote:
>
> > Thought so. Let me try and create a reproducable test case and let you
> > know what i find
> >
> > Paul
> >
> > Sent from my phone. Message may be brief and contain typos.
> >
> >
> > On 26 Apr 2017 13:35, "Romain Manni-Bucau" <rmannibucau@gmail.com>
> wrote:
> >
> >> Hi
> >>
> >> Shouldn't be possible since it would assume this flow:
> >>
> >> thread1. start tx                  | thread2. -
> >> thread1. create the entry    | thread2. -
> >> thread1. serialize the entry | thread2. -
> >> thread1. commit tx              | thread2. - find the entry
> >> thread1.                              | thread2. - fails
> >>
> >> The commit will happen
> >> in org.apache.openejb.server.cxf.ejb.EjbMethodInvoker#invoke where the
> >> serialization happens after
> >> in org.apache.cxf.jaxb.io.DataWriterImpl#write(java.lang.Object,
> >> org.apache.cxf.service.model.MessagePartInfo, T)
> >>
> >> Only case it should be possible to happen is if you wrapped jaxws
> >> servlet/layer with a custom transaction management (through a filter for
> >> instance) which would start/commit outside default JAXWS handling.
> >>
> >>
> >> Romain Manni-Bucau
> >> @rmannibucau <https://twitter.com/rmannibucau> |  Blog
> >> <https://blog-rmannibucau.rhcloud.com> | Old Blog
> >> <http://rmannibucau.wordpress.com> | Github <
> >> https://github.com/rmannibucau> |
> >> LinkedIn <https://www.linkedin.com/in/rmannibucau> | JavaEE Factory
> >> <https://javaeefactory-rmannibucau.rhcloud.com>
> >>
> >> 2017-04-26 12:59 GMT+02:00 Paul Carter-Brown <
> >> paul.carter-brown@smilecoms.com>:
> >>
> >> > Hi
> >> >
> >> > I have a call flow as follows in tomee:
> >> >
> >> > 1. Client calls jaxws service that adds a row into mysql table. EJB is
> >> > using JTA with eclipselink JPA entity bean. Seevice returns the
> primary
> >> key
> >> > of the row just added.
> >> > 2. Client uses returned soap message that contains the primary key and
> >> > calls a second service that does a select for the row in question.
> >> >
> >> > The service in 1 and 2 is in the same tomee instance and caching in
> jpa
> >> is
> >> > disabled. Tx isolation isread committed.
> >> >
> >> > Under high load and concurrency doing about 1000 tps i get about a 20%
> >> > failure rate where the service at stage 2 cannot find the row inserted
> >> at
> >> > stage 1. The row is inserted at some stage as i do see it in the db.
> >> Its as
> >> > though service 1 is returning prior to the database having committed
> the
> >> > data. My understanding is that this should not be possible as it would
> >> > create all sorts of inconsistencies. Is what i am observing expected
> >> > behaviour?
> >> >
> >> > Paul
> >> >
> >> > Sent from my phone. Message may be brief and contain typos.
> >> >
> >> > --
> >> >
> >> >
> >> > This email is subject to the disclaimer of Smile Communications at
> >> > http://www.smilecoms.com/home/email-disclaimer/ <
> >> http://www.smilecoms.com/
> >> > disclaimer>
> >> >
> >> >
> >>
> >
>
>
> --
>
> *Paul Carter-Brown*
>
> *Group Chief Information Officer*
>
> *Smile Communications Pty (Ltd)       *
> Smile +234 (0) 702 000 1234
> Mobile +27 (0) 83 4427 179
> Skype PaulC-B
> paul.carter-brown@smilecoms.com
> www.smilecoms.com
>
> --
>
>
> This email is subject to the disclaimer of Smile Communications at
> http://www.smilecoms.com/home/email-disclaimer/ <http://www.smilecoms.com/
> disclaimer>
>
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message