Hello,
We have application written in Axon. So far we used synchronous processing and everything was fine. Now we switched to asychronous and we are trying to test our app with it. So I wrote simple test, which is sending commands to command bus parallely. For examle in threadPool=4 invoicationCount=20. I’m trying different scales as well.
There are two (maybe) separate problems:
1.
We are getting DB deadlocks (postgresql). Most often in SagaRepository, but just probably because its used heavily. I was able to spot deadlocks in different repositories as well. Deadlock exeption:
`
javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement
at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.jpa.spi.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1771) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.jpa.spi.AbstractQueryImpl.executeUpdate(AbstractQueryImpl.java:87) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]
at org.axonframework.saga.repository.jpa.JpaSagaRepository.updateSaga(JpaSagaRepository.java:173) ~[axon-core-2.3.1.jar:2.3.1]
at org.axonframework.saga.repository.AbstractSagaRepository.commit(AbstractSagaRepository.java:69) ~[axon-core-2.3.1.jar:2.3.1]
at org.axonframework.saga.annotation.AsyncSagaEventProcessor.persistProcessedSagas(AsyncSagaEventProcessor.java:221) [axon-core-2.3.1.jar:2.3.1]
at org.axonframework.saga.annotation.AsyncSagaEventProcessor.doProcessEvent(AsyncSagaEventProcessor.java:147) [axon-core-2.3.1.jar:2.3.1]
at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:118) [axon-core-2.3.1.jar:2.3.1]
at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:49) [axon-core-2.3.1.jar:2.3.1]
at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133) [disruptor-3.2.0.jar:na]
at org.axonframework.saga.annotation.AsyncAnnotatedSagaManager$StartDetectingRunnable.run(AsyncAnnotatedSagaManager.java:478) [axon-core-2.3.1.jar:2.3.1]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_67]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_67]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
at org.hibernate.dialect.PostgreSQL81Dialect$2.convert(PostgreSQL81Dialect.java:416) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:190) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:62) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3281) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3183) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3525) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:159) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:349) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.event.internal.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:67) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.internal.SessionImpl.autoFlushIfRequired(SessionImpl.java:1191) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.internal.SessionImpl.executeUpdate(SessionImpl.java:1281) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.internal.QueryImpl.executeUpdate(QueryImpl.java:118) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.jpa.internal.QueryImpl.internalExecuteUpdate(QueryImpl.java:371) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]
at org.hibernate.jpa.spi.AbstractQueryImpl.executeUpdate(AbstractQueryImpl.java:78) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]
… 11 common frames omitted
Caused by: org.postgresql.util.PSQLException: ERROR: deadlock detected
Detail: Process 5040 waits for ShareLock on transaction 83222; blocked by process 9160.
Process 9160 waits for ExclusiveLock on tuple (0,153) of relation 79072 of database 19886; blocked by process 5040.
Hint: See server log for query details.
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2157) ~[postgresql-9.2-1002.jdbc4.jar:na]
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1886) ~[postgresql-9.2-1002.jdbc4.jar:na]
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255) ~[postgresql-9.2-1002.jdbc4.jar:na]
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:555) ~[postgresql-9.2-1002.jdbc4.jar:na]
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:417) ~[postgresql-9.2-1002.jdbc4.jar:na]
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:363) ~[postgresql-9.2-1002.jdbc4.jar:na]
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:1423) ~[c3p0-0.9.5-pre8.jar:0.9.5-pre8]
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:187) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]
… 25 common frames omitted
`
Another problem is that commands which I sending are manipulating with some amount (among other things). And when I send 50 commands - amount should be increased by 50. But its just for example 40 (When there is no deadlock of course ). As I was debugging this, I was able to tell that one thread incereases amount from 0 to 1, but another thread still see 0 and increases the value also to 1. Everything else looks fine. BusinessTransactions and Sagas are finished, other data looks fine. But this amount is on one shared Aggregate root and is manupulated by multiple threads/commands. Of course - bigger the thread pool is - the money lost is bigger
From both problems I suspect transactions, but I’m not really sure. I would appreciate maybe hint how to deal with transactions in Axon.
Our project setup is probably typical - Spring, Hibernate, DB - posgreSQL
If more configuration details are needed - just tell.
Thanks