Ok, at that point maybe try to reproduce it on a small sample on github -
goal is to share with us your setup more or less but not confidential data.
You can use:
<dependency>
<groupId>com.wix</groupId>
<artifactId>wix-embedded-mysql</artifactId>
<version>2.1.4</version>
</dependency>
And in java:
EmbeddedMysql.anEmbeddedMysql(MysqldConfig
.aMysqldConfig(Version.v5_7_17)
.withPort(Integer.parseInt(port))
.withUser("user", "pass")
.build());
final EmbeddedMysql mysql = builder.start()
.addSchema(SchemaConfig.aSchemaConfig("test").build());
To write a test with a running MySQL (first time you launch it downloads
mysql so it can be a bit long but then it is cached.
This way we could grab it locally and investigate a bit more.
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-27 6:06 GMT+02:00 Paul Carter-Brown <paul.carter-br...@smilecoms.com
>:
> 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 SmileConnectionLifecycleInterc
> eptor:
> > > > >
> > > > > public class SmileConnectionLifecycleInterceptor implements
> > > > > ConnectionLifecycleInterceptor {
> > > > >
> > > > > private static final Logger log =
> > > > > LoggerFactory.getLogger(SmileConnectionLifecycleInterc
> eptor.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>
>
>
