8 Replies Latest reply on Dec 8, 2011 11:52 AM by Sanne Grinovero

    Poor performance for distributed transaction commit.

    Sudheer Krishna Novice

      Hi,

       

      We are using infinispan for caching in replicated mode. And i have teh following observations .

       

      1. we are using atomikos transaction manager to manage transaction between infinispan and mysql database.

      2. Spring annotations are used to hide teh transaction configurations.

      3. After profiling i figure out that commit of teh transaction takes a long time (more than 50%, ie the commit time is equal to teh db operatiosn time).

      4. i currently have a single node in teh cluster

      5. There is a cache event lsitener , which listens to teh cache updates (i have checked teh timing for this listener code , and it only takes 1-2 milliseconds, just to ensure its not taking the time during commit.)

       

      We use teh follwing cache configration

       


      <default>


      <jmxStatistics enabled="true" />


      <transaction transactionManagerLookupClass="com.tspex.cache.infinispan.TransactionManagerLookUp"



      syncRollbackPhase="true" syncCommitPhase="true" useEagerLocking="false"/>


      <clustering mode="replication" >



      <!-- sync replTimeout="20000" -->



      <async/>


      </clustering>


      <locking isolationLevel="REPEATABLE_READ" concurrencyLevel="500"  useLockStriping="false"/>

      </default>

       

       

      I have also tried with syncRollbackPhase and syncCommitPhase set to false , there is no mucg difference in timings.

       

      All teh timing are goen in two operations

       

      com.atomikos.icatch.imp.Coorainator.prepare() and  com.atomikos.icatch.imp.Coorainator.commit().

       

      The time for these two operations is around 70-80 milliseconds. Is this expected timing ? OR is there anything wrong in my configuration ?

        • 1. Re: Poor performance for distributed transaction commit.
          Sudheer Krishna Novice

          Is there any way to debug/profile why there is so much wait during prepare and commit phase ?.

           

          Since its a single node in teh cluster i was expecting it not to wait on reply over teh network.

          • 2. Re: Poor performance for distributed transaction commit.
            Sanne Grinovero Master

            Is there any way to debug/profile why there is so much wait during prepare and commit phase ?

            Yes! Using a profiler

             

             

            Since its a single node in teh cluster i was expecting it not to wait on reply over teh network.

            I agree, it's unlikely that it's actually waiting for network operations. It shouldn't even send any packet out, after the boot phase as finished verifying there are no other nodes in the same network.

            • 3. Re: Poor performance for distributed transaction commit.
              Sudheer Krishna Novice

              yes off course i am using a profiler . i am using jvisualvm to do teh profiling.

               

              The stack just shows upto teh fact that atomokos waitforreplies() is taking most of the time.  I am interested in knowing what exactly it is waiting for.

               

              Can u give me any hints which will help me to profile this ?

              • 4. Re: Poor performance for distributed transaction commit.
                Sudheer Krishna Novice

                Also could it be anything to do with cache listeners ? I am listening to transaction comiited event and performing soem business logic there.

                 

                Althought i have profiled teh business logic and it doesnt take more than 2 milliseconds.

                 

                 

                Coudl be soemthing to do with atomikos as well .. trying to check that out.

                • 5. Re: Poor performance for distributed transaction commit.
                  Sudheer Krishna Novice

                  I did a little bit of debugging and was able to get teh follwing details. 

                   

                  Insteqd of running stress tests i fired a single request and enabled atomikos logging and was able to get the following. Teh sinel requsets performs a single db operation and a cache opertaion within a transaction. And i observer that teh prepare and commit for database(mysql) is very fast.But the prepare and commit phase for infinispan takes a long time (around 25 milliseconds)

                   

                   

                  Atomikos registering participants

                   

                  //MYSQL

                  1803568 2011-12-08 14:11:32,735 [serviceTaskExecutor-2] INFO  atomikos.println:110  - addParticipant ( XAResourceTransaction: 746D5F74737065782D6170702D636F6E7461696E65725F3130303437303030303032:746D5F74737065782D6170702D636F6E7461696E65725F31343935 ) for transaction tm_tspex-app-container_10047000002

                  1803568 2011-12-08 14:11:32,735 [serviceTaskExecutor-2] INFO  atomikos.println:110  - XAResource.start ( 746D5F74737065782D6170702D636F6E7461696E65725F3130303437303030303032:746D5F74737065782D6170702D636F6E7461696E65725F31343935 , XAResource.TMNOFLAGS ) on resource MAIN-MYSQL-CONNECTION represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4MysqlXAConnection@68f92ae2

                   

                  //INFINISPAN

                  1803580 2011-12-08 14:11:32,747 [serviceTaskExecutor-2] INFO  atomikos.println:110  - addParticipant ( XAResourceTransaction: 746D5F74737065782D6170702D636F6E7461696E65725F3130303437303030303032:5472616E73616374696F6E5861416461707465727B6C6F63616C5472616E73616374696F6E3D4C6F63616C5861343936 ) for transaction tm_tspex-app-container_10047000002

                  1803581 2011-12-08 14:11:32,748 [serviceTaskExecutor-2] INFO  atomikos.println:110  - XAResource.start ( 746D5F74737065782D6170702D636F6E7461696E65725F3130303437303030303032:5472616E73616374696F6E5861416461707465727B6C6F63616C5472616E73616374696F6E3D4C6F63616C5861343936 , XAResource.TMNOFLAGS ) on resource TransactionXaAdapter{localTransaction=LocalXa represented by XAResource instance TransactionXaAdapter{localTransaction=LocalXaTransaction{xid=null} LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, transaction=tm_tspex-app-container_10047000002} org.infinispan.transaction.xa.LocalXaTransaction@d61cedbd}

                   

                   

                  //RESPONSE FROM INFINISPAN

                   

                  1803586 2011-12-08 14:11:32,753 [Atomikos:26] INFO  atomikos.println:110  - XAResource.end ( 746D5F74737065782D6170702D636F6E7461696E65725F3130303437303030303032:5472616E73616374696F6E5861416461707465727B6C6F63616C5472616E73616374696F6E3D4C6F63616C5861343936 , XAResource.TMSUCCESS ) on resource TransactionXaAdapter{localTransaction=LocalXa represented by XAResource instance TransactionXaAdapter{localTransaction=LocalXaTransaction{xid=tm_tspex-app-container_10047000002TransactionXaAdapter{localTransaction=LocalXa496} LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, transaction=tm_tspex-app-container_10047000002} org.infinispan.transaction.xa.LocalXaTransaction@d61cedbd}

                  1803591 2011-12-08 14:11:32,758 [Atomikos:26] INFO  atomikos.println:110  - XAResource.prepare ( 746D5F74737065782D6170702D636F6E7461696E65725F3130303437303030303032:5472616E73616374696F6E5861416461707465727B6C6F63616C5472616E73616374696F6E3D4C6F63616C5861343936 ) returning OK on resource TransactionXaAdapter{localTransaction=LocalXa represented by XAResource instance TransactionXaAdapter{localTransaction=LocalXaTransaction{xid=tm_tspex-app-container_10047000002TransactionXaAdapter{localTransaction=LocalXa496} LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, transaction=tm_tspex-app-container_10047000002} org.infinispan.transaction.xa.LocalXaTransaction@d61cedbd}

                  1803606 2011-12-08 14:11:32,773 [Atomikos:26] INFO  atomikos.println:110  - XAResource.commit ( 746D5F74737065782D6170702D636F6E7461696E65725F3130303437303030303032:5472616E73616374696F6E5861416461707465727B6C6F63616C5472616E73616374696F6E3D4C6F63616C5861343936 , false ) on resource TransactionXaAdapter{localTransaction=LocalXa represented by XAResource instance TransactionXaAdapter{localTransaction=LocalXaTransaction{xid=tm_tspex-app-container_10047000002TransactionXaAdapter{localTransaction=LocalXa496} LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, transaction=tm_tspex-app-container_10047000002} org.infinispan.transaction.xa.LocalXaTransaction@d61cedbd}

                   

                   

                   

                  //RESPONSE FROM MYSQL

                   

                  1803605 2011-12-08 14:11:32,772 [Atomikos:24] INFO  atomikos.println:110  - XAResource.prepare ( 746D5F74737065782D6170702D636F6E7461696E65725F3130303437303030303032:746D5F74737065782D6170702D636F6E7461696E65725F31343935 ) returning OK on resource MAIN-MYSQL-CONNECTION represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4MysqlXAConnection@68f92ae2

                  1803606 2011-12-08 14:11:32,773 [Atomikos:24] INFO  atomikos.println:110  - XAResource.commit ( 746D5F74737065782D6170702D636F6E7461696E65725F3130303437303030303032:746D5F74737065782D6170702D636F6E7461696E65725F31343935 , false ) on resource MAIN-MYSQL-CONNECTION represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4MysqlXAConnection@68f92ae2

                  • 6. Re: Poor performance for distributed transaction commit.
                    Sanne Grinovero Master

                    that's detinitely unexpected. What version of Infinispan are we talking about?

                     

                    could you try also <clustering mode="distribution" > ?

                    • 7. Re: Poor performance for distributed transaction commit.
                      Sudheer Krishna Novice

                      Sorry , it was my bad , i slightly miss interrupted teh logs. I gave few more runs and realized that it was teh response from  mysql which was taking long tiem and hence atomikos was waiting for teh commit phase untill it gets  a response for prepare.

                       

                      Thanks Grinovero.