-
1. Re: Poor performance for distributed transaction commit.
sudheerk84 Dec 7, 2011 9:11 AM (in response to sudheerk84)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.
sannegrinovero Dec 7, 2011 9:23 AM (in response to sudheerk84)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.
sudheerk84 Dec 7, 2011 9:41 AM (in response to sannegrinovero)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.
sudheerk84 Dec 7, 2011 9:53 AM (in response to sudheerk84)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.
sudheerk84 Dec 8, 2011 9:40 AM (in response to sudheerk84)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.
sannegrinovero Dec 8, 2011 10:38 AM (in response to sudheerk84)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.
sudheerk84 Dec 8, 2011 11:34 AM (in response to sannegrinovero)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.
-
8. Re: Poor performance for distributed transaction commit.
sannegrinovero Dec 8, 2011 11:52 AM (in response to sudheerk84)I'm glad to know that! thanks