No. Autocommit is off Paul
Sent from my phone. Message may be brief and contain typos. On 27 Apr 2017 12:47 a.m., "Romain Manni-Bucau" <rmannibu...@gmail.com> wrote: > Are you in autocommit mode? > > Le 26 avr. 2017 22:37, "Paul Carter-Brown" <paul.carter-brown@smilecoms. > com> > a écrit : > > > Hi, > > > > Unfortunately, the same result with dbcp2. I also turned on mysql general > > query log and can see the commit come through after the select comes in > on > > another connection: > > > > > > 2017-04-26T19:46:22.243742Z 20038 Query INSERT INTO > > SmileDB.customer_profile ... <removed> > > 2017-04-26T19:46:22.245984Z 20038 Query SELECT LAST_INSERT_ID() > > 2017-04-26T19:46:22.291193Z 20038 Query select @@session.tx_read_only > > 2017-04-26T19:46:22.317914Z 20031 Query SET autocommit=0 > > 2017-04-26T19:46:22.318088Z 20031 Query SELECT * FROM > > SmileDB.customer_profile WHERE CUSTOMER_PROFILE_ID=1267253 AND > STATUS='AC' > > 2017-04-26T19:46:22.372481Z 20038 Query commit > > > > > > And here is the log of the lifecycle listener getting commit called: > > > > 2017/04/26 21:46:22.293 FINE [TomEE-Exec-31][301][com. > > smilecoms.commons.base.lifecycle.SmileConnectionLifecycleInterc > > eptor.commit] > > |Commit called > > > > > > > > > > On 26 April 2017 at 17:12, Romain Manni-Bucau <rmannibu...@gmail.com> > > wrote: > > > > > 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/rmannibuca > > > u> | > > > 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-br...@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:159 > > > 9) > > > > 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(TxRequ > > > ired.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(WsSe > > > rvlet.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$RequestCap > > > turer.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(Http11Proce > > > ssor.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-br...@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" <rmannibu...@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-br...@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-br...@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> > > > > > > > > > > > > > > > > > > > -- > > > > *Paul Carter-Brown* > > > > *Group Chief Information Officer* > > > > *Smile Communications Pty (Ltd) * > > Smile +234 (0) 702 000 1234 <+234%20702%20000%201234> > > Mobile +27 (0) 83 4427 179 > > Skype PaulC-B > > paul.carter-br...@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> > > > > > -- This email is subject to the disclaimer of Smile Communications at http://www.smilecoms.com/home/email-disclaimer/ <http://www.smilecoms.com/disclaimer>
