4

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
3
  • Is it consistently around the 17/18,000 mark - and presumably not at a specific time of day that it starts to occur (e.g. ruling out 'other' network or database activity? Commented Oct 29, 2018 at 11:01
  • Yes, we have done several tests, started at different points of the day (starting in the morning, or in the evening, etc). We are always seeing these results around the same amount of successfull publishes Commented Oct 29, 2018 at 11:24
  • I've been seeing the exact same exception; at roughly the same intervals as you Harald. We get around 10-15k items through successfully but eventually we start seeing CannotAcquireLockException errors in the logs.
    – Josh Hebb
    Commented Nov 8, 2018 at 1:19

1 Answer 1

6

After a lot of research, we found the following. The microservices were installed on a Linux environment, and were started using SystemD scripts.

After investigating the /var/log/messages file, which contains various stdout output messages, including the messages created by the microservices, we noticed that the microservices crashed after an OutOfMemoryException. Note that this log did not appear in the standard java logs that the deployer would output.

some example log we could see

 [ERROR] [10/31/2018 22:51:20.052] [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1504] [akka.actor.ActorSystemImpl(ProcessingAkkaSpringContext)] Uncaught error from thread [ProcessingAkkaSpringContext-akka.actor.default-dispatcher-1504] shutting down JVM since 'akka.jvm-exit-on-fatal-error' is enabled
 java.lang.OutOfMemoryError: GC overhead limit exceeded
 at org.apache.xml.utils.ObjectVector.<init>(ObjectVector.java:83)
 at org.apache.xpath.compiler.OpMap.<init>(OpMap.java:75)
 at org.apache.xpath.compiler.Compiler.<init>(Compiler.java:90)
 at org.apache.xpath.XPath.<init>(XPath.java:224)
 at org.apache.xalan.processor.StylesheetHandler.createMatchPatternXPath(StylesheetHandler.java:173)
 at org.apache.xalan.processor.XSLTAttributeDef.processPATTERN(XSLTAttributeDef.java:841)
 at org.apache.xalan.processor.XSLTAttributeDef.processValue(XSLTAttributeDef.java:1411)
 at org.apache.xalan.processor.XSLTAttributeDef.setAttrValue(XSLTAttributeDef.java:1601)
 at org.apache.xalan.processor.XSLTElementProcessor.setPropertiesFromAttributes(XSLTElementProcessor.java:355)
 at org.apache.xalan.processor.XSLTElementProcessor.setPropertiesFromAttributes(XSLTElementProcessor.java:267)
 at org.apache.xalan.processor.ProcessorTemplateElem.startElement(ProcessorTemplateElem.java:78)
 at org.apache.xalan.processor.StylesheetHandler.startElement(StylesheetHandler.java:623)
 at org.apache.xerces.parsers.AbstractSAXParser.startElement(Unknown Source)
 at org.apache.xerces.impl.XMLNSDocumentScannerImpl.scanStartElement(Unknown Source)
 at org.apache.xerces.impl.XMLDocumentFragmentScannerImpl$FragmentContentDispatcher.dispatch(Unknown Source)
 at org.apache.xerces.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unknown Source)
 at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source)
 at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source)
 at org.apache.xerces.parsers.XMLParser.parse(Unknown Source)
 at org.apache.xerces.parsers.AbstractSAXParser.parse(Unknown Source)
 at org.apache.xerces.jaxp.SAXParserImpl$JAXPSAXParser.parse(Unknown Source)
 at org.apache.xalan.processor.TransformerFactoryImpl.newTemplates(TransformerFactoryImpl.java:917)
 at org.apache.xalan.processor.TransformerFactoryImpl.newTransformer(TransformerFactoryImpl.java:771)
 at com.tridion.broker.meta.custom.XSLTCustomMetaProcessor.getTransformer(XSLTCustomMetaProcessor.java:100)
 at com.tridion.broker.meta.custom.XSLTCustomMetaProcessor.process(XSLTCustomMetaProcessor.java:74)
 at com.tridion.broker.meta.custom.FlatteningCustomMetaEmbeddedFieldsProcessor.process(FlatteningCustomMetaEmbeddedFieldsProcessor.java:20)
 at com.tridion.storage.persistence.JPAItemDAO.setFullCustomMeta(JPAItemDAO.java:281)
 at com.tridion.storage.caching.CachedItemDAO.setFullCustomMeta(CachedItemDAO.java:191)
 at com.tridion.storage.deploy.ComponentMetaHandler.deploy(ComponentMetaHandler.java:58)
 at com.tridion.deployer.DeploymentHandler.deploy(DeploymentHandler.java:101)
 at com.tridion.deployer.DeploymentHandler.deploy(DeploymentHandler.java:69)
 at com.tridion.deployer.modules.ComponentDeploy.processComponent(ComponentDeploy.java:167)
Oct 31 22:51:53 ****systemd: ****-deployer-worker.service: main process exited, code=exited, status=255/n/a
Oct 31 22:51:53 ****systemd: Unit ****-deployer-worker.service entered failed state.
Oct 31 22:51:53 ****systemd: ****-deployer-worker.service failed.

With this information, we increased the maximum memory of the deployer worker services (from the default 1024m to 2048m) - see https://docs.sdl.com/LiveContent/content/en-US/SDL%20Web-v5/GUID-882178AA-A7E5-451B-8CD3-9F06D967F9BE on more info on how to do this.

This seemed to help a lot. We now are able to publish all of our pages, without the service suddenly crashing, resulting in all items being stuck in 'waiting for deployment', and eventually failing.

Additionally, we also configured our SystemD scripts to automatically restart the services in case they would crash (see https://www.freedesktop.org/software/systemd/man/systemd.service.html#Restart= on more info on how to do this). While this is not really a solution to the problem, it also helps, since the services then automatically recover from such unforeseen failures.

1
  • We are experiencing a very similar issue. Deployer Worker (scaled-out scenario) runs out of heap memory and crashes its Docker container. It self-heals, but not happy with it crashing in the first place. We increased min/max heap allocation to 2048MB. This helped, for a while, but still issue happens on sudden publish bursts. I believe there is a relation with the size of the Transport Package (containing many large binaries) and the fact the Worker is multi-threaded (default 11 internal processors). Have you changed any other settings regarding GC/memory? Any recommendations? Thanks a lot! Commented Jul 30, 2020 at 12:35

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.