We are seeing some erratic behaviour with our deployer-worker microservices when doing mass publishes.
In our environment, we have the following setup
- Two publisher CM servers
- One Deployer endpoint
- Two deployer workers
- ActiveMQ for queuing publish messages
- All latest hotfixes have been implemented We have also set the number of worker threads to some lower values than the defaults, but this doesn’t make much difference, we keep getting these errors.
Publishing is working fine for a normal publish, even larger publishes of over 5000 pages is working fine.
However, we consistently get problems when we do a mass publish of over 25000 pages. When doing such tests, after about 17000-18000 items we start getting deadlock errors, and eventually the deployers shut down. As a result, the remaining items to be published are never processed, and timeout in the publisher
We are seeing the following error messages/warnings. We also always see that the warning “Session/EntityManager” is closed is the last item that gets logged, it looks like after that the service shuts down
2018-10-26 11:12:16,448 ERROR SqlExceptionHelper - Transaction (Process ID 77) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
2018-10-26 11:12:16,449 ERROR ExceptionMapperStandardImpl - HHH000346: Error during managed flush [org.hibernate.exception.LockAcquisitionException: could not execute statement]
2018-10-26 11:12:16,451 WARN StepActor - Step 'TridionUnzipStep' for 'tcm:0-5218799-66560' failed with message: org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement
2018-10-26 11:12:16,457 ERROR StepActor - Step 'TridionUnzipStep' for 'tcm:0-5218799-66560' can NOT retry
2018-10-26 11:12:16,458 ERROR StepActor - Step 'TridionUnzipStep' for 'tcm:0-5218799-66560':
org.springframework.dao.CannotAcquireLockException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement
at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:269)
at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:244)
at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:521)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:761)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:730)
at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:487)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:291)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
at com.sun.proxy.$Proxy114.storeData(Unknown Source)
at com.sdl.delivery.deployer.engine.pipeline.actor.StepActor.execute(StepActor.scala:75)
at com.sdl.delivery.deployer.engine.pipeline.actor.StepActor.com$sdl$delivery$deployer$engine$pipeline$actor$StepActor$$processStep(StepActor.scala:57)
at com.sdl.delivery.deployer.engine.pipeline.actor.StepActor$$anonfun$receive$1.applyOrElse(StepActor.scala:40)
at akka.actor.Actor$class.aroundReceive(Actor.scala:480)
at com.sdl.delivery.deployer.engine.pipeline.actor.StepActor.aroundReceive(StepActor.scala:26)
at akka.actor.ActorCell.receiveMessage(ActorCell.scala:526)
at akka.actor.ActorCell.invoke(ActorCell.scala:495)
at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257)
at akka.dispatch.Mailbox.run(Mailbox.scala:224)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:123)
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.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:207)
at org.hibernate.dialect.identity.GetGeneratedKeysDelegate.executeAndExtract(GetGeneratedKeysDelegate.java:57)
at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:42)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2840)
at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3411)
at org.hibernate.action.internal.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:81)
at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:619)
at org.hibernate.engine.spi.ActionQueue.addResolvedEntityInsertAction(ActionQueue.java:273)
at org.hibernate.engine.spi.ActionQueue.addInsertAction(ActionQueue.java:254)
at org.hibernate.engine.spi.ActionQueue.addAction(ActionQueue.java:299)
at org.hibernate.event.internal.AbstractSaveEventListener.addInsertAction(AbstractSaveEventListener.java:318)
at org.hibernate.event.internal.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:275)
at org.hibernate.event.internal.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:182)
at org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:113)
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.internal.SessionImpl.firePersistOnFlush(SessionImpl.java:825)
at org.hibernate.internal.SessionImpl.persistOnFlush(SessionImpl.java:818)
at org.hibernate.engine.spi.CascadingActions$8.cascade(CascadingActions.java:341)
at org.hibernate.engine.internal.Cascade.cascadeToOne(Cascade.java:391)
at org.hibernate.engine.internal.Cascade.cascadeAssociation(Cascade.java:316)
at org.hibernate.engine.internal.Cascade.cascadeProperty(Cascade.java:155)
at org.hibernate.engine.internal.Cascade.cascadeCollectionElements(Cascade.java:424)
at org.hibernate.engine.internal.Cascade.cascadeCollection(Cascade.java:356)
at org.hibernate.engine.internal.Cascade.cascadeAssociation(Cascade.java:319)
at org.hibernate.engine.internal.Cascade.cascadeProperty(Cascade.java:155)
at org.hibernate.engine.internal.Cascade.cascade(Cascade.java:104)
at org.hibernate.event.internal.AbstractFlushingEventListener.cascadeOnFlush(AbstractFlushingEventListener.java:150)
at org.hibernate.event.internal.AbstractFlushingEventListener.prepareEntityFlushes(AbstractFlushingEventListener.java:141)
at org.hibernate.event.internal.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:74)
at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:38)
at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1407)
at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:477)
at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3170)
at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2384)
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:467)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:146)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$100(JdbcResourceLocalTransactionCoordinatorImpl.java:38)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:220)
at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:68)
at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:517)
... 20 common frames omitted
Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 77) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:217)
at com.microsoft.sqlserver.jdbc.SQLServerStatement.getNextResult(SQLServerStatement.java:1655)
at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(SQLServerPreparedStatement.java:440)
at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(SQLServerPreparedStatement.java:385)
at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7505)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:2444)
at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:191)
at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:166)
at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeUpdate(SQLServerPreparedStatement.java:328)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:204)
... 61 common frames omitted
2018-10-26 11:12:16,500 WARN TridionCleanupStep - Could not locate original zip location for execution id tcm:0-5218799-66560
2018-10-26 14:27:54,832 WARN StepActor - Step 'ComponentDeploy' for 'tcm:0-5224239-66560' failed with message: org.springframework.beans.factory.BeanCreationNotAllowedException: Error creating bean with name 'transactionManager': Singleton bean creation not allowed while the singletons of this factory are in destruction (Do not request a bean from a BeanFactory in a destroy method implementation!)
2018-10-26 14:27:54,835 ERROR TransactionInterceptor - Application exception overridden by rollback exception
org.hibernate.LazyInitializationException: failed to lazily initialize a collection of role: com.sdl.delivery.deployer.jpa.domain.StepEntity.executionProperties, could not initialize proxy - the owning Session was closed
at org.hibernate.collection.internal.AbstractPersistentCollection.throwLazyInitializationException(AbstractPersistentCollection.java:582)
at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:209)
at org.hibernate.collection.internal.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:561)
at org.hibernate.collection.internal.AbstractPersistentCollection.read(AbstractPersistentCollection.java:132)
at org.hibernate.collection.internal.PersistentSet.iterator(PersistentSet.java:163)
at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1798)
at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:580)
at java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:270)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1382)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
at com.sdl.delivery.deployer.state.HybridStepDataStore.getExecutionPropertiesForCriteria(HybridStepDataStore.java:245)
at com.sdl.delivery.deployer.state.HybridStepDataStore.findData(HybridStepDataStore.java:234)
at com.sdl.delivery.deployer.state.HybridStepDataStore.findData(HybridStepDataStore.java:147)
at sun.reflect.GeneratedMethodAccessor69.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
at com.sun.proxy.$Proxy114.findData(Unknown Source)
at com.sdl.delivery.deployer.engine.step.StepDataProviderImpl.findStepData(StepDataProviderImpl.java:47)
at com.sdl.delivery.deployer.api.processing.pipeline.StepDataProvider.findSingleStepData(StepDataProvider.java:74)
at com.sdl.delivery.deployer.steps.TridionCleanupStep.cleanupOrMoveZipPackage(TridionCleanupStep.java:136)
at com.sdl.delivery.deployer.steps.TridionCleanupStep.process(TridionCleanupStep.java:78)
at com.sdl.delivery.deployer.engine.pipeline.actor.StepActor.execute(StepActor.scala:72)
at com.sdl.delivery.deployer.engine.pipeline.actor.StepActor.com$sdl$delivery$deployer$engine$pipeline$actor$StepActor$$processStep(StepActor.scala:57)
at com.sdl.delivery.deployer.engine.pipeline.actor.StepActor$$anonfun$receive$1.applyOrElse(StepActor.scala:40)
at akka.actor.Actor$class.aroundReceive(Actor.scala:480)
at com.sdl.delivery.deployer.engine.pipeline.actor.StepActor.aroundReceive(StepActor.scala:26)
at akka.actor.ActorCell.receiveMessage(ActorCell.scala:526)
at akka.actor.ActorCell.invoke(ActorCell.scala:495)
at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257)
at akka.dispatch.Mailbox.run(Mailbox.scala:224)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2018-10-26 14:27:54,835 WARN StepActor - Step 'TridionCleanupStep' for 'tcm:0-5224282-66560' failed with message: java.lang.IllegalStateException: Session/EntityManager is closed