Event could not be persisted when I do load test

Kyle · September 13, 2019, 9:02am

Sorry for my poor english.

When I do a load test in my application, request get stuck and exception throws.
I get into the axon source code and find the unitOfWork.attachTransaction(transactionManager); consume all the db connections and the event could not be persisted when it tries to cause lack of db connection and the UOW could not commit I guess and so it just wait for timeout.

Here is my application configuration:

axon 4.2 with asynchronousCommandBus and other default config.* spring boot 2.0.7
hikaripool default config
jpa transaction manager

org.axonframework.eventsourcing.eventstore.EventStoreException: An event for aggregate [1568363981533708449] at sequence [0] could not be persisted
at org.axonframework.eventsourcing.eventstore.AbstractEventStorageEngine.handlePersistenceException(AbstractEventStorageEngine.java:121)
at org.axonframework.eventsourcing.eventstore.jpa.JpaEventStorageEngine.lambda$appendEvents$6(JpaEventStorageEngine.java:286)
at org.axonframework.common.transaction.TransactionManager.executeInTransaction(TransactionManager.java:47)
at org.axonframework.eventsourcing.eventstore.jpa.JpaEventStorageEngine.appendEvents(JpaEventStorageEngine.java:279)
at org.axonframework.eventsourcing.eventstore.AbstractEventStorageEngine.appendEvents(AbstractEventStorageEngine.java:94)
at org.axonframework.eventsourcing.eventstore.AbstractEventStore.prepareCommit(AbstractEventStore.java:63)
at org.axonframework.eventhandling.AbstractEventBus.doWithEvents(AbstractEventBus.java:218)
at org.axonframework.eventhandling.AbstractEventBus.lambda$null$8(AbstractEventBus.java:152)
at org.axonframework.messaging.unitofwork.MessageProcessingContext.notifyHandlers(MessageProcessingContext.java:71)
at org.axonframework.messaging.unitofwork.DefaultUnitOfWork.notifyHandlers(DefaultUnitOfWork.java:106)
at org.axonframework.messaging.unitofwork.AbstractUnitOfWork.changePhase(AbstractUnitOfWork.java:222)
at org.axonframework.messaging.unitofwork.AbstractUnitOfWork.commitAsRoot(AbstractUnitOfWork.java:83)
at org.axonframework.messaging.unitofwork.AbstractUnitOfWork.commit(AbstractUnitOfWork.java:71)
at org.axonframework.messaging.unitofwork.DefaultUnitOfWork.executeWithResult(DefaultUnitOfWork.java:92)
at org.axonframework.commandhandling.SimpleCommandBus.handle(SimpleCommandBus.java:176)
at org.axonframework.commandhandling.AsynchronousCommandBus.lambda$handle$0(AsynchronousCommandBus.java:89)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:844)
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.JDBCConnectionException: unable to obtain isolated JDBC connection
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:149)
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:157)
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:164)
at org.hibernate.internal.SessionImpl.firePersist(SessionImpl.java:790)
at org.hibernate.internal.SessionImpl.persist(SessionImpl.java:768)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:305)
at com.sun.proxy.$Proxy176.persist(Unknown Source)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1492)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
at org.axonframework.eventsourcing.eventstore.jpa.JpaEventStorageEngine.lambda$appendEvents$6(JpaEventStorageEngine.java:281)
… 17 more
Caused by: org.hibernate.exception.JDBCConnectionException: unable to obtain isolated JDBC connection
at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:48)
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:97)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcIsolationDelegate.delegateWork(JdbcIsolationDelegate.java:103)
at org.hibernate.id.enhanced.TableStructure$1.getNextValue(TableStructure.java:125)
at org.hibernate.id.enhanced.NoopOptimizer.generate(NoopOptimizer.java:40)
at org.hibernate.id.enhanced.SequenceStyleGenerator.generate(SequenceStyleGenerator.java:452)
at org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:105)
at org.hibernate.jpa.event.internal.core.JpaPersistEventListener.saveWithGeneratedId(JpaPersistEventListener.java:67)
at org.hibernate.event.internal.DefaultPersistEventListener.entityIsTransient(DefaultPersistEventListener.java:189)
at org.hibernate.event.internal.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:132)
at org.hibernate.event.internal.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:58)
at org.hibernate.internal.SessionImpl.firePersist(SessionImpl.java:783)
… 34 more
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30007ms.
at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:669)
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:183)
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:148)
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
at com.zaxxer.hikari.HikariDataSource$$FastClassBySpringCGLIB$$eeb1ae86.invoke()
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:746)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:136)
at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:124)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)
at com.zaxxer.hikari.HikariDataSource$$EnhancerBySpringCGLIB$$f8229bd4.getConnection()
at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:35)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcIsolationDelegate.delegateWork(JdbcIsolationDelegate.java:48)
… 43 more

Steven_van_Beelen · September 13, 2019, 9:46am

Hi Kevin/Kyle,

For every message you’ll dispatch Axon will attach a transaction to it through the TransactionManager.
As you’re using Spring Boot, a Transaction Manager will be auto configured for you.

This transaction which is started upon dispatching a command will be used to store your events.
Additionally, when command handling is resolved entirely, meaning the Unit Of Work for said command is finalized, the transaction will be resolved too.
If you have to many concurrent operations of this on a single instance, specifically if it increases the pool size of Hikari, then this exception is to be expected I guess.

So, what’s the pool size you’ve set for Hikari?

The default ExecutorService used by the AsynchronousCommandBus is a CachedThreadPoolExecutor.
If my mind serves me right, this will just create new threads to dispatch commands as it deems necessary.

Thus, in a performance test scenario, that might eat up all your connection quickly too.
Adjusted the ExecutorService used by your AsynchronousCommandBus to be maxed to, let’s say 10 threads, could also solve things.

Hope some of these guidelines help you out Kyle!

Cheers,
Steven

Kyle · September 13, 2019, 3:39pm

Hi Steven,

Thanks for your quick reply.
I use the default Hikari configuration which means the pool size is 10.
And changed the ExecutorService to FixedThreadPoolExecutor with core size and maximum size to 10 and the problem solved.
The performance is bad due to the I/O latency (Calling a third-party service inside the aggregate command handler, I’m not sure this is a bad practice or a common case) and low currency.

This transaction which is started upon dispatching a command will be used to store your events.

Steven_van_Beelen · September 18, 2019, 11:53am

Hi Kyle,

Firstly, I am happy to hear my suggestion solved the problem for you!

Secondly, I would like to strongly advice not to make (third-party) service calls from within an Aggregate.
In doing so, you are essentially locking up that Aggregate instance for any other concurrent operations.

Additionally, the Aggregate Root should be regarded as the consistency boundary within which commands are validated and “factualized” by publishing an event.
Any (third party) service calls should either be made as a reaction to said event or prior to dispatching the command (in for example a “external command handler”).

Again, I hopes this helps you out Kyle!

Cheers,
Steven