tomee-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Paul Carter-Brown <paul.carter-br...@smilecoms.com>
Subject Re: JTA Commit Timing
Date Wed, 26 Apr 2017 14:45:24 GMT
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.SmileConnectionLifecycleInterceptor.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