Atomikos Forum
Varying performance on commit |
I have quite a tricky problem. We have a server using Spring+JTA+Hibernate+Atomikos+ActiveMQ. We use @Transactional spring annotations to start and commit transactions and works fine on our integration server with fairly good performance with a slow hard drive, quite a lot processes running. This means that a REST request implying a transaction will fully complete in less than 100 ms.
However on our production server which is tremendously faster, we have a huge performance problem. The same war using the same database (MySQL but in a slightly different version) has varying performance on completing the same request with similar data : it can have response time between 100ms and 2500ms!
Activating the trace shows that time was lost mostly AFTER the REST method returns which made me think of a potential issue on Atomikos. Investigating further more showed that the time between the commit message sent by application and sync2sync afterCompletion method was where the time was lost.
The requested resource is always the same so it's not a matter of hibernate cache not hit IMHO.
here are the logs:
01:19:05.619 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO o.a.c.i.LoggingInInterceptor - Inbound Message
----------------------------
ID: 34
Address: https://server/ws/app
Http-Method: GET
Content-Type:
Headers: {Accept=[*/*], accept-encoding=[gzip,deflate,sdch], Accept-Language=[en-US,en;q=0.8,fr;q=0.6], Authorization=[Basic qsd=], Cache-Control=[no-cache], connection=[keep-alive], Content-Length=[0], Content-Type=[null], cookie=[_ga=GA1.2.1881840552.1416843239; appKey=null; serverVersion=1.1%20build%2012; locale=en], Postman-Token=[b0159d78-2390-9578-f462-f0cea43110b5], user-agent=[Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.122 Safari/537.36]}
--------------------------------------
01:19:05.620 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.BaseTransactionManager - createCompositeTransaction ( 300000 ): created new ROOT transaction with id 176.31.240.140.tm2110500003
01:19:05.620 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.icatch.jta.Sync2Sync@703fc592 ) for transaction 176.31.240.140.tm2110500003
01:19:05.620 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.icatch.jta.Sync2Sync@6ac42dd0 ) for transaction 176.31.240.140.tm2110500003
01:19:05.621 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'XADBMS': getConnection ( null )...
01:19:05.621 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'XADBMS': init...
01:19:05.622 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - addParticipant ( XAResourceTransaction: 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 ) for transaction 176.31.240.140.tm2110500003
01:19:05.622 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.d.xa.XAResourceTransaction - XAResource.start ( 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 , XAResource.TMNOFLAGS ) on resource XADBMS represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@ad9697e
01:19:05.622 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.jdbc.AtomikosConnectionProxy$JdbcRequeueSynchronization@781a4488 ) for transaction 176.31.240.140.tm2110500003
01:19:05.622 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling prepareStatement(select this_.APP_KEY as APP_KEY1_0_1_, this_.TENANT_ID as TENANT_I2_0_1_, this_.APP_SECRET as APP_SECR3_0_1_, this_.CUSTOMER_ID as CUSTOMER6_0_1_, this_.ICON as ICON4_0_1_, this_.NAME as NAME5_0_1_, customer2_.CUSTOMER_ID as CUSTOMER1_8_0_, customer2_.TENANT_ID as TENANT_I2_8_0_, customer2_.ADDRESS as ADDRESS3_8_0_, customer2_.CITY as CITY4_8_0_, customer2_.COUNTRY as COUNTRY5_8_0_, customer2_.ICON as ICON6_8_0_, customer2_.NAME as NAME7_8_0_, customer2_.PHONE_NUMBER as PHONE_NU8_8_0_, customer2_.ZIP as ZIP9_8_0_ from APP this_ left outer join CUSTOMER customer2_ on this_.CUSTOMER_ID=customer2_.CUSTOMER_ID where this_.tenant_id = ?)...
01:19:05.624 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: isClosed()...
01:19:05.624 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling getWarnings...
01:19:05.624 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling clearWarnings...
01:19:05.624 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: close()...
01:19:05.624 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.d.xa.XAResourceTransaction - XAResource.end ( 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 , XAResource.TMSUCCESS ) on resource XADBMS represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@ad9697e
01:19:05.625 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'XADBMS': getConnection ( null )...
01:19:05.625 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'XADBMS': init...
01:19:05.625 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - addParticipant ( XAResourceTransaction: 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 ) for transaction 176.31.240.140.tm2110500003
01:19:05.625 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.d.xa.XAResourceTransaction - XAResource.start ( 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 , XAResource.TMJOIN ) on resource XADBMS represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@ad9697e
01:19:05.625 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.jdbc.AtomikosConnectionProxy$JdbcRequeueSynchronization@781a4488 ) for transaction 176.31.240.140.tm2110500003
01:19:05.626 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling prepareStatement(select tags0_.APP_APP_KEY as APP_APP_4_0_0_, tags0_.TAG_ID as TAG_ID1_18_0_, tags0_.TAG_ID as TAG_ID1_18_1_, tags0_.TENANT_ID as TENANT_I2_18_1_, tags0_.APP_APP_KEY as APP_APP_4_18_1_, tags0_.TAG_NAME as TAG_NAME3_18_1_ from TAG tags0_ where tags0_.APP_APP_KEY=?)...
01:19:05.626 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: isClosed()...
01:19:05.626 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling getWarnings...
01:19:05.626 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling clearWarnings...
01:19:05.626 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: close()...
01:19:05.626 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.d.xa.XAResourceTransaction - XAResource.end ( 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 , XAResource.TMSUCCESS ) on resource XADBMS represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@ad9697e
01:19:05.627 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'XADBMS': getConnection ( null )...
01:19:05.627 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'XADBMS': init...
01:19:05.627 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - addParticipant ( XAResourceTransaction: 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 ) for transaction 176.31.240.140.tm2110500003
01:19:05.627 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.d.xa.XAResourceTransaction - XAResource.start ( 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 , XAResource.TMJOIN ) on resource XADBMS represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@ad9697e
01:19:05.628 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.jdbc.AtomikosConnectionProxy$JdbcRequeueSynchronization@781a4488 ) for transaction 176.31.240.140.tm2110500003
01:19:05.628 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling prepareStatement(select appconfigu0_.APP_APP_KEY as APP_APP_4_0_0_, appconfigu0_.APPCONFIGURATION_ID as APPCONFI1_5_0_, appconfigu0_.APPCONFIGURATION_ID as APPCONFI1_5_1_, appconfigu0_.TENANT_ID as TENANT_I2_5_1_, appconfigu0_.APP_APP_KEY as APP_APP_4_5_1_, appconfigu0_.PLATFORM as PLATFORM3_5_1_, appconfigu0_.ANDROID_PACKAGE as ANDROID_1_1_1_, appconfigu0_.DEV_GCM_KEY as DEV_GCM_2_1_1_, appconfigu0_.PROD_GCM_KEY as PROD_GCM3_1_1_, appconfigu0_.APNS_DEV_CERTIFICATE as APNS_DEV1_2_1_, appconfigu0_.APNS_DEV_CERTIFICATE_PASSWORD as APNS_DEV2_2_1_, appconfigu0_.APNS_PROD_CERTIFICATE as APNS_PRO3_2_1_, appconfigu0_.APNS_PROD_CERTIFICATE_PASSWORD as APNS_PRO4_2_1_, appconfigu0_.WINDOWS8_CERTIFICATE as WINDOWS1_4_1_, appconfigu0_.WINDOWS8_PASSWORD as WINDOWS2_4_1_, appconfigu0_.WINDOWS8_SID as WINDOWS3_4_1_, appconfigu0_.WINDOWS8_SECRET as WINDOWS4_4_1_, appconfigu0_.APNS_DEV_CERTIFICATE as APNS_DEV1_3_1_, appconfigu0_.APNS_DEV_CERTIFICATE_PASSWORD as APNS_DEV2_3_1_, appconfigu0_.APNS_PROD_CERTIFICATE as APNS_PRO3_3_1_, appconfigu0_.APNS_PROD_CERTIFICATE_PASSWORD as APNS_PRO4_3_1_, appconfigu0_.clazz_ as clazz_1_ from ( select APPCONFIGURATION_ID, TENANT_ID, PLATFORM, APP_APP_KEY, ANDROID_PACKAGE, DEV_GCM_KEY, PROD_GCM_KEY, null as APNS_DEV_CERTIFICATE, null as APNS_DEV_CERTIFICATE_PASSWORD, null as APNS_PROD_CERTIFICATE, null as APNS_PROD_CERTIFICATE_PASSWORD, null as WINDOWS8_CERTIFICATE, null as WINDOWS8_PASSWORD, null as WINDOWS8_SID, null as WINDOWS8_SECRET, 1 as clazz_ from APP_CONFIG_ANDROID union select APPCONFIGURATION_ID, TENANT_ID, PLATFORM, APP_APP_KEY, null as ANDROID_PACKAGE, null as DEV_GCM_KEY, null as PROD_GCM_KEY, APNS_DEV_CERTIFICATE, APNS_DEV_CERTIFICATE_PASSWORD, APNS_PROD_CERTIFICATE, APNS_PROD_CERTIFICATE_PASSWORD, null as WINDOWS8_CERTIFICATE, null as WINDOWS8_PASSWORD, null as WINDOWS8_SID, null as WINDOWS8_SECRET, 2 as clazz_ from APP_CONFIG_APPLE union select APPCONFIGURATION_ID, TENANT_ID, PLATFORM, APP_APP_KEY, null as ANDROID_PACKAGE, null as DEV_GCM_KEY, null as PROD_GCM_KEY, null as APNS_DEV_CERTIFICATE, null as APNS_DEV_CERTIFICATE_PASSWORD, null as APNS_PROD_CERTIFICATE, null as APNS_PROD_CERTIFICATE_PASSWORD, WINDOWS8_CERTIFICATE, WINDOWS8_PASSWORD, WINDOWS8_SID, WINDOWS8_SECRET, 3 as clazz_ from APP_CONFIG_WINDOWS8 union select APPCONFIGURATION_ID, TENANT_ID, PLATFORM, APP_APP_KEY, null as ANDROID_PACKAGE, null as DEV_GCM_KEY, null as PROD_GCM_KEY, APNS_DEV_CERTIFICATE, APNS_DEV_CERTIFICATE_PASSWORD, APNS_PROD_CERTIFICATE, APNS_PROD_CERTIFICATE_PASSWORD, null as WINDOWS8_CERTIFICATE, null as WINDOWS8_PASSWORD, null as WINDOWS8_SID, null as WINDOWS8_SECRET, 4 as clazz_ from APP_CONFIG_APPLE_MAC ) appconfigu0_ where appconfigu0_.APP_APP_KEY=?)...
01:19:05.630 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: isClosed()...
01:19:05.630 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling getWarnings...
01:19:05.630 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling clearWarnings...
01:19:05.630 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: close()...
01:19:05.630 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.d.xa.XAResourceTransaction - XAResource.end ( 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 , XAResource.TMSUCCESS ) on resource XADBMS represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@ad9697e
01:19:05.646 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#6-1] INFO c.a.jms.AtomikosJmsXaSessionProxy - atomikos xa session proxy for resource XAactiveMQ: Calling commit/rollback is not allowed on a managed session!
01:19:05.646 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#6-1] INFO c.a.i.imp.CompositeTransactionImp - commit() done (by application) of transaction 176.31.240.140.tm2109100003
01:19:05.651 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO com.atomikos.icatch.jta.Sync2Sync - beforeCompletion() called on Synchronization: org.hibernate.context.internal.JTASessionContext$CleanupSync@29af7d74
01:19:05.652 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO com.atomikos.icatch.jta.Sync2Sync - beforeCompletion() called on Synchronization: org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization@4055600d
++++++++++++++++++ LOOK HERE the transaction is committed
01:19:05.652 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - commit() done (by application) of transaction 176.31.240.140.tm2110500003
01:19:05.685 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#12-1] INFO c.a.d.xa.XAResourceTransaction - XAResource.end ( 3137362E33312E3234302E3134302E746D32313037333030303033:3137362E33312E3234302E3134302E746D3231303732 , XAResource.TMSUCCESS ) on resource XAactiveMQ represented by XAResource instance TransactionContext{transactionId=XID:[1096044365,globalId=3137362e33312e3234302e3134302e746d32313037333030303033,branchId=3137362e33312e3234302e3134302e746d3231303732]}
<A LOOOOOT of JMS transactions logs here>
01:19:07.415 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#14-1] INFO c.a.j.AtomikosJmsMessageConsumerProxy - atomikos MessageConsumer proxy for ActiveMQMessageConsumer { value=ID:black-49394-1416959665766-5:16:4:1, started=true }: receive ( 1000 , null )...
01:19:07.415 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#14-1] INFO c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.jms.ConsumerProducerSupport$JmsRequeueSynchronization@e44bb30 ) for transaction 176.31.240.140.tm2113000003
01:19:07.414 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#11-1] INFO c.a.j.AtomikosJmsMessageConsumerProxy - atomikos MessageConsumer proxy for ActiveMQMessageConsumer { value=ID:black-49394-1416959665766-5:13:3:1, started=true }: receive ( 1000 )...
++++++++++++++++++ LOOK HERE the transaction is completed
01:19:07.415 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO com.atomikos.icatch.jta.Sync2Sync - afterCompletion ( STATUS_COMMITTED ) called on Synchronization: org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization@4055600d
01:19:07.414 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#1-1] INFO c.a.i.imp.CompositeTransactionImp - addParticipant ( XAResourceTransaction: 3137362E33312E3234302E3134302E746D32313133313030303033:3137362E33312E3234302E3134302E746D3231313239 ) for transaction 176.31.240.140.tm2113100003
01:19:07.415 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO com.atomikos.icatch.jta.Sync2Sync - afterCompletion ( STATUS_COMMITTED ) called on Synchronization: org.hibernate.context.internal.JTASessionContext$CleanupSync@29af7d74
01:19:07.416 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO o.a.c.i.LoggingOutInterceptor - Outbound Message
---------------------------
ID: 34
Response-Code: 200
Content-Type: application/json
Headers: {Content-Type=[application/json], Date=[Wed, 26 Nov 2014 00:19:07 GMT]}
Payload: [{json payload here}]
--------------------------------------
here we see that it takes almost 2s to process the request. The connection pool is set to a high value. There's a lot of heap available. I'm running out of ideas.
Has someone already had a similar issue?
However on our production server which is tremendously faster, we have a huge performance problem. The same war using the same database (MySQL but in a slightly different version) has varying performance on completing the same request with similar data : it can have response time between 100ms and 2500ms!
Activating the trace shows that time was lost mostly AFTER the REST method returns which made me think of a potential issue on Atomikos. Investigating further more showed that the time between the commit message sent by application and sync2sync afterCompletion method was where the time was lost.
The requested resource is always the same so it's not a matter of hibernate cache not hit IMHO.
here are the logs:
01:19:05.619 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO o.a.c.i.LoggingInInterceptor - Inbound Message
----------------------------
ID: 34
Address: https://server/ws/app
Http-Method: GET
Content-Type:
Headers: {Accept=[*/*], accept-encoding=[gzip,deflate,sdch], Accept-Language=[en-US,en;q=0.8,fr;q=0.6], Authorization=[Basic qsd=], Cache-Control=[no-cache], connection=[keep-alive], Content-Length=[0], Content-Type=[null], cookie=[_ga=GA1.2.1881840552.1416843239; appKey=null; serverVersion=1.1%20build%2012; locale=en], Postman-Token=[b0159d78-2390-9578-f462-f0cea43110b5], user-agent=[Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.122 Safari/537.36]}
--------------------------------------
01:19:05.620 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.BaseTransactionManager - createCompositeTransaction ( 300000 ): created new ROOT transaction with id 176.31.240.140.tm2110500003
01:19:05.620 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.icatch.jta.Sync2Sync@703fc592 ) for transaction 176.31.240.140.tm2110500003
01:19:05.620 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.icatch.jta.Sync2Sync@6ac42dd0 ) for transaction 176.31.240.140.tm2110500003
01:19:05.621 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'XADBMS': getConnection ( null )...
01:19:05.621 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'XADBMS': init...
01:19:05.622 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - addParticipant ( XAResourceTransaction: 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 ) for transaction 176.31.240.140.tm2110500003
01:19:05.622 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.d.xa.XAResourceTransaction - XAResource.start ( 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 , XAResource.TMNOFLAGS ) on resource XADBMS represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@ad9697e
01:19:05.622 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.jdbc.AtomikosConnectionProxy$JdbcRequeueSynchronization@781a4488 ) for transaction 176.31.240.140.tm2110500003
01:19:05.622 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling prepareStatement(select this_.APP_KEY as APP_KEY1_0_1_, this_.TENANT_ID as TENANT_I2_0_1_, this_.APP_SECRET as APP_SECR3_0_1_, this_.CUSTOMER_ID as CUSTOMER6_0_1_, this_.ICON as ICON4_0_1_, this_.NAME as NAME5_0_1_, customer2_.CUSTOMER_ID as CUSTOMER1_8_0_, customer2_.TENANT_ID as TENANT_I2_8_0_, customer2_.ADDRESS as ADDRESS3_8_0_, customer2_.CITY as CITY4_8_0_, customer2_.COUNTRY as COUNTRY5_8_0_, customer2_.ICON as ICON6_8_0_, customer2_.NAME as NAME7_8_0_, customer2_.PHONE_NUMBER as PHONE_NU8_8_0_, customer2_.ZIP as ZIP9_8_0_ from APP this_ left outer join CUSTOMER customer2_ on this_.CUSTOMER_ID=customer2_.CUSTOMER_ID where this_.tenant_id = ?)...
01:19:05.624 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: isClosed()...
01:19:05.624 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling getWarnings...
01:19:05.624 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling clearWarnings...
01:19:05.624 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: close()...
01:19:05.624 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.d.xa.XAResourceTransaction - XAResource.end ( 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 , XAResource.TMSUCCESS ) on resource XADBMS represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@ad9697e
01:19:05.625 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'XADBMS': getConnection ( null )...
01:19:05.625 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'XADBMS': init...
01:19:05.625 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - addParticipant ( XAResourceTransaction: 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 ) for transaction 176.31.240.140.tm2110500003
01:19:05.625 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.d.xa.XAResourceTransaction - XAResource.start ( 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 , XAResource.TMJOIN ) on resource XADBMS represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@ad9697e
01:19:05.625 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.jdbc.AtomikosConnectionProxy$JdbcRequeueSynchronization@781a4488 ) for transaction 176.31.240.140.tm2110500003
01:19:05.626 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling prepareStatement(select tags0_.APP_APP_KEY as APP_APP_4_0_0_, tags0_.TAG_ID as TAG_ID1_18_0_, tags0_.TAG_ID as TAG_ID1_18_1_, tags0_.TENANT_ID as TENANT_I2_18_1_, tags0_.APP_APP_KEY as APP_APP_4_18_1_, tags0_.TAG_NAME as TAG_NAME3_18_1_ from TAG tags0_ where tags0_.APP_APP_KEY=?)...
01:19:05.626 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: isClosed()...
01:19:05.626 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling getWarnings...
01:19:05.626 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling clearWarnings...
01:19:05.626 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: close()...
01:19:05.626 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.d.xa.XAResourceTransaction - XAResource.end ( 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 , XAResource.TMSUCCESS ) on resource XADBMS represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@ad9697e
01:19:05.627 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'XADBMS': getConnection ( null )...
01:19:05.627 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AbstractDataSourceBean - AtomikosDataSoureBean 'XADBMS': init...
01:19:05.627 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - addParticipant ( XAResourceTransaction: 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 ) for transaction 176.31.240.140.tm2110500003
01:19:05.627 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.d.xa.XAResourceTransaction - XAResource.start ( 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 , XAResource.TMJOIN ) on resource XADBMS represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@ad9697e
01:19:05.628 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.jdbc.AtomikosConnectionProxy$JdbcRequeueSynchronization@781a4488 ) for transaction 176.31.240.140.tm2110500003
01:19:05.628 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling prepareStatement(select appconfigu0_.APP_APP_KEY as APP_APP_4_0_0_, appconfigu0_.APPCONFIGURATION_ID as APPCONFI1_5_0_, appconfigu0_.APPCONFIGURATION_ID as APPCONFI1_5_1_, appconfigu0_.TENANT_ID as TENANT_I2_5_1_, appconfigu0_.APP_APP_KEY as APP_APP_4_5_1_, appconfigu0_.PLATFORM as PLATFORM3_5_1_, appconfigu0_.ANDROID_PACKAGE as ANDROID_1_1_1_, appconfigu0_.DEV_GCM_KEY as DEV_GCM_2_1_1_, appconfigu0_.PROD_GCM_KEY as PROD_GCM3_1_1_, appconfigu0_.APNS_DEV_CERTIFICATE as APNS_DEV1_2_1_, appconfigu0_.APNS_DEV_CERTIFICATE_PASSWORD as APNS_DEV2_2_1_, appconfigu0_.APNS_PROD_CERTIFICATE as APNS_PRO3_2_1_, appconfigu0_.APNS_PROD_CERTIFICATE_PASSWORD as APNS_PRO4_2_1_, appconfigu0_.WINDOWS8_CERTIFICATE as WINDOWS1_4_1_, appconfigu0_.WINDOWS8_PASSWORD as WINDOWS2_4_1_, appconfigu0_.WINDOWS8_SID as WINDOWS3_4_1_, appconfigu0_.WINDOWS8_SECRET as WINDOWS4_4_1_, appconfigu0_.APNS_DEV_CERTIFICATE as APNS_DEV1_3_1_, appconfigu0_.APNS_DEV_CERTIFICATE_PASSWORD as APNS_DEV2_3_1_, appconfigu0_.APNS_PROD_CERTIFICATE as APNS_PRO3_3_1_, appconfigu0_.APNS_PROD_CERTIFICATE_PASSWORD as APNS_PRO4_3_1_, appconfigu0_.clazz_ as clazz_1_ from ( select APPCONFIGURATION_ID, TENANT_ID, PLATFORM, APP_APP_KEY, ANDROID_PACKAGE, DEV_GCM_KEY, PROD_GCM_KEY, null as APNS_DEV_CERTIFICATE, null as APNS_DEV_CERTIFICATE_PASSWORD, null as APNS_PROD_CERTIFICATE, null as APNS_PROD_CERTIFICATE_PASSWORD, null as WINDOWS8_CERTIFICATE, null as WINDOWS8_PASSWORD, null as WINDOWS8_SID, null as WINDOWS8_SECRET, 1 as clazz_ from APP_CONFIG_ANDROID union select APPCONFIGURATION_ID, TENANT_ID, PLATFORM, APP_APP_KEY, null as ANDROID_PACKAGE, null as DEV_GCM_KEY, null as PROD_GCM_KEY, APNS_DEV_CERTIFICATE, APNS_DEV_CERTIFICATE_PASSWORD, APNS_PROD_CERTIFICATE, APNS_PROD_CERTIFICATE_PASSWORD, null as WINDOWS8_CERTIFICATE, null as WINDOWS8_PASSWORD, null as WINDOWS8_SID, null as WINDOWS8_SECRET, 2 as clazz_ from APP_CONFIG_APPLE union select APPCONFIGURATION_ID, TENANT_ID, PLATFORM, APP_APP_KEY, null as ANDROID_PACKAGE, null as DEV_GCM_KEY, null as PROD_GCM_KEY, null as APNS_DEV_CERTIFICATE, null as APNS_DEV_CERTIFICATE_PASSWORD, null as APNS_PROD_CERTIFICATE, null as APNS_PROD_CERTIFICATE_PASSWORD, WINDOWS8_CERTIFICATE, WINDOWS8_PASSWORD, WINDOWS8_SID, WINDOWS8_SECRET, 3 as clazz_ from APP_CONFIG_WINDOWS8 union select APPCONFIGURATION_ID, TENANT_ID, PLATFORM, APP_APP_KEY, null as ANDROID_PACKAGE, null as DEV_GCM_KEY, null as PROD_GCM_KEY, APNS_DEV_CERTIFICATE, APNS_DEV_CERTIFICATE_PASSWORD, APNS_PROD_CERTIFICATE, APNS_PROD_CERTIFICATE_PASSWORD, null as WINDOWS8_CERTIFICATE, null as WINDOWS8_PASSWORD, null as WINDOWS8_SID, null as WINDOWS8_SECRET, 4 as clazz_ from APP_CONFIG_APPLE_MAC ) appconfigu0_ where appconfigu0_.APP_APP_KEY=?)...
01:19:05.630 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: isClosed()...
01:19:05.630 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling getWarnings...
01:19:05.630 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: calling clearWarnings...
01:19:05.630 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.jdbc.AtomikosConnectionProxy - atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper@71a05d80: close()...
01:19:05.630 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.d.xa.XAResourceTransaction - XAResource.end ( 3137362E33312E3234302E3134302E746D32313130353030303033:3137362E33312E3234302E3134302E746D3231313034 , XAResource.TMSUCCESS ) on resource XADBMS represented by XAResource instance com.mysql.jdbc.jdbc2.optional.JDBC4SuspendableXAConnection@ad9697e
01:19:05.646 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#6-1] INFO c.a.jms.AtomikosJmsXaSessionProxy - atomikos xa session proxy for resource XAactiveMQ: Calling commit/rollback is not allowed on a managed session!
01:19:05.646 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#6-1] INFO c.a.i.imp.CompositeTransactionImp - commit() done (by application) of transaction 176.31.240.140.tm2109100003
01:19:05.651 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO com.atomikos.icatch.jta.Sync2Sync - beforeCompletion() called on Synchronization: org.hibernate.context.internal.JTASessionContext$CleanupSync@29af7d74
01:19:05.652 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO com.atomikos.icatch.jta.Sync2Sync - beforeCompletion() called on Synchronization: org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization@4055600d
++++++++++++++++++ LOOK HERE the transaction is committed
01:19:05.652 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO c.a.i.imp.CompositeTransactionImp - commit() done (by application) of transaction 176.31.240.140.tm2110500003
01:19:05.685 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#12-1] INFO c.a.d.xa.XAResourceTransaction - XAResource.end ( 3137362E33312E3234302E3134302E746D32313037333030303033:3137362E33312E3234302E3134302E746D3231303732 , XAResource.TMSUCCESS ) on resource XAactiveMQ represented by XAResource instance TransactionContext{transactionId=XID:[1096044365,globalId=3137362e33312e3234302e3134302e746d32313037333030303033,branchId=3137362e33312e3234302e3134302e746d3231303732]}
<A LOOOOOT of JMS transactions logs here>
01:19:07.415 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#14-1] INFO c.a.j.AtomikosJmsMessageConsumerProxy - atomikos MessageConsumer proxy for ActiveMQMessageConsumer { value=ID:black-49394-1416959665766-5:16:4:1, started=true }: receive ( 1000 , null )...
01:19:07.415 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#14-1] INFO c.a.i.imp.CompositeTransactionImp - registerSynchronization ( com.atomikos.jms.ConsumerProducerSupport$JmsRequeueSynchronization@e44bb30 ) for transaction 176.31.240.140.tm2113000003
01:19:07.414 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#11-1] INFO c.a.j.AtomikosJmsMessageConsumerProxy - atomikos MessageConsumer proxy for ActiveMQMessageConsumer { value=ID:black-49394-1416959665766-5:13:3:1, started=true }: receive ( 1000 )...
++++++++++++++++++ LOOK HERE the transaction is completed
01:19:07.415 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO com.atomikos.icatch.jta.Sync2Sync - afterCompletion ( STATUS_COMMITTED ) called on Synchronization: org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization@4055600d
01:19:07.414 !! [org.springframework.jms.listener.DefaultMessageListenerContainer#1-1] INFO c.a.i.imp.CompositeTransactionImp - addParticipant ( XAResourceTransaction: 3137362E33312E3234302E3134302E746D32313133313030303033:3137362E33312E3234302E3134302E746D3231313239 ) for transaction 176.31.240.140.tm2113100003
01:19:07.415 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO com.atomikos.icatch.jta.Sync2Sync - afterCompletion ( STATUS_COMMITTED ) called on Synchronization: org.hibernate.context.internal.JTASessionContext$CleanupSync@29af7d74
01:19:07.416 !MYCOMPANY! [ajp-bio-8009-exec-3] INFO o.a.c.i.LoggingOutInterceptor - Outbound Message
---------------------------
ID: 34
Response-Code: 200
Content-Type: application/json
Headers: {Content-Type=[application/json], Date=[Wed, 26 Nov 2014 00:19:07 GMT]}
Payload: [{json payload here}]
--------------------------------------
here we see that it takes almost 2s to process the request. The connection pool is set to a high value. There's a lot of heap available. I'm running out of ideas.
Has someone already had a similar issue?
I did some more investigations and installing on several different servers revealed no performance issue.
I started profiling with jprofiler and it appears that on my prod server there is a lot of locking on StreamObjectLog. I have quite a few JMS queues (about 10) and as much as listeners and it may the cause of the problem.
The other difference between this server and others is that it's a ubuntu tomcat7 package that is installed whereas for other servers I directly used the package downloaded from tomcat website.
any ideas what could be the issue ?
I started profiling with jprofiler and it appears that on my prod server there is a lot of locking on StreamObjectLog. I have quite a few JMS queues (about 10) and as much as listeners and it may the cause of the problem.
The other difference between this server and others is that it's a ubuntu tomcat7 package that is installed whereas for other servers I directly used the package downloaded from tomcat website.
any ideas what could be the issue ?
Using the tomcat version coming directly from Apache tomcat website seems to solve the problem. I suspect something like permission issues. As a matter of fact, in the case of ubuntu install, tomcat is running as user tomcat7, not root. My problem doesn't appear if I use root user to run the server.
has anyone encountered the same problem?
has anyone encountered the same problem?
Other recent topics