7

I have a content author who is trying to publish a bundle. The bundle ends up publishing a pretty big payload of stuff. There are 23 components in the bundle. When I publish it Tridion picks up 93 total items to publish. I image everyone's response will be don't to publish that many items at once. But if Tridion can't publish very much stuff why does it let you do it? I have a hard time with that response because it seems like once I have more then 20 items Tridion publishing becomes very brittle.

The deployment dies during the commit phase.

Here is what the cd_deployer log say:

2015-01-21 19:12:26,183 WARN  PreCommitPhase - Failed to Prepare: tcm:0-16605-66560 error: org.hibernate.ResourceClosedException: This TransactionCoordinator has been closed
2015-01-21 19:12:26,183 WARN  DeployPipelineExecutor - Phase: Deployment Prepare Commit Phase failure message: Unable to prepare transaction: tcm:0-16605-66560 for transaction: tcm:0-16605-66560
2015-01-21 19:12:26,183 DEBUG DeployPipelineExecutor - Failure in Phase: Deployment Prepare Commit Phase attempt: 11 for transaction: tcm:0-16605-66560
2015-01-21 19:12:26,183 ERROR DeployPipelineExecutor - Final attempt in Phase: Deployment Prepare Commit Phase failed for transaction: tcm:0-16605-66560
2015-01-21 19:12:26,183 ERROR DeployPipelineExecutor - Original stack trace for transaction: tcm:0-16605-66560
com.tridion.deployer.ProcessingException: Unable to prepare transaction: tcm:0-16605-66560
    at com.tridion.deployer.phases.PreCommitPhase.handleFailure(PreCommitPhase.java:131) ~[cd_deployer.jar:na]
    at com.tridion.deployer.phases.PreCommitPhase.execute(PreCommitPhase.java:111) ~[cd_deployer.jar:na]
    at com.tridion.deployer.phases.DeployPipelineExecutor.runMainExecutePhase(DeployPipelineExecutor.java:198) [cd_deployer.jar:na]
    at com.tridion.deployer.phases.DeployPipelineExecutor.doExecute(DeployPipelineExecutor.java:100) [cd_deployer.jar:na]
    at com.tridion.deployer.phases.DeployPipelineExecutor.execute(DeployPipelineExecutor.java:64) [cd_deployer.jar:na]
    at com.tridion.deployer.TransactionManager.handleDeployPackage(TransactionManager.java:82) [cd_deployer.jar:na]
    at com.tridion.deployer.queue.QueueLocationHandler$1.run(QueueLocationHandler.java:180) [cd_deployer.jar:na]
    at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [na:1.7.0_45]
    at java.util.concurrent.FutureTask.run(Unknown Source) [na:1.7.0_45]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [na:1.7.0_45]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [na:1.7.0_45]
    at java.lang.Thread.run(Unknown Source) [na:1.7.0_45]
Caused by: javax.persistence.PersistenceException: org.hibernate.ResourceClosedException: This TransactionCoordinator has been closed
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1361) ~[hibernate-entitymanager.jar:4.0.1.Final]
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1289) ~[hibernate-entitymanager.jar:4.0.1.Final]
    at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:261) ~[hibernate-entitymanager.jar:4.0.1.Final]
    at com.tridion.storage.persistence.JPABaseDAO.executeQueryListResult(JPABaseDAO.java:281) ~[cd_datalayer.jar:na]
    at com.tridion.storage.persistence.JPABaseDAO.executeQueryListResult(JPABaseDAO.java:249) ~[cd_datalayer.jar:na]
    at com.tridion.storage.persistence.JPABaseDAO.executeQueryListResult(JPABaseDAO.java:220) ~[cd_datalayer.jar:na]
    at com.tridion.storage.persistence.JPABaseDAO.executeQuerySingleResult(JPABaseDAO.java:199) ~[cd_datalayer.jar:na]
    at com.tridion.storage.persistence.JPABinaryVariantDAO.findByPrimaryKey(JPABinaryVariantDAO.java:91) ~[cd_datalayer.jar:na]
    at com.tridion.storage.caching.CachedBinaryVariantDAO.findByPrimaryKey(CachedBinaryVariantDAO.java:56) ~[cd_datalayer.jar:na]
    at com.tridion.storage.deploy.workers.BinaryWorker.doDeploy(BinaryWorker.java:87) ~[cd_datalayer.jar:na]
    at com.tridion.deployer.model.transaction.TransactionLogItemWorker.doWork(TransactionLogItemWorker.java:27) ~[cd_model.jar:na]
    at com.tridion.deployer.phases.PreCommitPhase.runPrepare(PreCommitPhase.java:155) ~[cd_deployer.jar:na]
    at com.tridion.deployer.phases.PreCommitPhase.execute(PreCommitPhase.java:101) ~[cd_deployer.jar:na]

UPDATE: Log from first error

DEBUG PreCommitPhase - Executing worker com.tridion.storage.deploy.workers.BinaryWorker@7dc98e93 on transaction: tcm:0-16605-66560 this is worker 135 of: 2226
2015-01-21 19:01:24,075 WARN  PreCommitPhase - Unable to store item inside current transaction: Unable to persist data entity
2015-01-21 19:01:24,075 WARN  PreCommitPhase - Failed to Prepare: tcm:0-16605-66560 error: Unable to store item inside current transaction
2015-01-21 19:01:24,075 WARN  DeployPipelineExecutor - Phase: Deployment Prepare Commit Phase failure message: Unable to prepare transaction: tcm:0-16605-66560 for transaction: tcm:0-16605-66560
2015-01-21 19:01:24,075 DEBUG DeployPipelineExecutor - Failure in Phase: Deployment Prepare Commit Phase attempt: 1 for transaction: tcm:0-16605-66560

Update 2: In the deployer logback I turn Root level to Debug (instead of off) and got some more info.

<root level="Debug">
    <appender-ref ref="rollingCoreLog"/>
</root>

Here is the additional log info

2015-01-23 11:49:06,282 ERROR StorageManagerTransactionMonitor - Rolling back a stale transaction: tcm:0-17016-66560, transaction was waiting for: 124364 ms.

The commit transaction looks like it has a 120 second window or it rolls back. I tried updating the deployer storage connection string this <Pool Type="jdbc2" Size="10" MonitorInterval="60" IdleTimeout="1200" CheckoutTimeout="1200"/> but that did not change anything.

We are using SQL Server 2012.

Improve this question
7
  • 1
    23 components / 93 items doesn't seem particularly large compared to some deployment packages I've seen before
    – David Forster
    Commented Jan 22, 2015 at 15:51
  • 1
    I definitely agree with David's view - I saw performance problems on deploying 1000+ items, but not low hundreds. Are you using Transactional deployment?
    – Nuno Linhares ♦
    Commented Jan 22, 2015 at 15:58
  • Well good news it "should" be able to do this. @NunoLinhares I believe we are using transactional deployment as the logs are giving transaction IDs. How do I confirm though?
    – ToddB
    Commented Jan 22, 2015 at 17:41
  • Note this line: "Failure in Phase: Deployment Prepare Commit Phase attempt: 11 for transaction: tcm:0-16605-66560". This means it's the 11th time the deployer tried to write something to storage. Usually the real error is only logged after the first attempt failed. Could you share that piece of log please?
    – Raimond
    Commented Jan 22, 2015 at 18:31
  • 1
    How many Workers do you have in your deployer config? Please try to isolate the DB transactions in the way Bjorn is describing. It seems like you're overloading the DB with a lot of writes which don't get committed in time.
    – Raimond
    Commented Jan 26, 2015 at 21:55

3 Answers 3

Reset to default
7

-- UPDATE -- The actual root cause turned out to be a swap/page file that was set too small on the DB. Setting it to a default/recommended value. -- End Update --

This issue is specific to database maintenance needing to be run on the Broker Database.

We followed Rick's suggestion and did a DB trace. However, this only showed connections timing out - as he pointed out. After trying to figure out what timeout settings to tweak without avail, we went back to review out DB maintenance plan.

The maintenance plan was set to only reorganize/rebuild indexes with page counts over 1000 pages as recommended by Microsoft (note: a page in this sense is the fundamental unit of data storage in SQL Server, not a Tridion Page). See more on PageCountLevel here: https://ola.hallengren.com/sql-server-index-and-statistics-maintenance.html

According to MS, anything under 1000 pages is small enough where it is not going to be affected by fragmentation, so our stats were never triggered because our Broker was under this threshold.

During our investigation into this issue we have manually updated all indices on the Broker database with fragmentation over 10%. We then retested publishing of a very deeply linked component with many binaries, and also retested the bundle mentioned in the question. It worked.

Improve this answer
0
5

The transaction IDs (like tcm:0-16605-66560) are Tridion Publish Transaction IDs (representing logical publishing transactions) which don't imply transactional deployment, but the error message "This TransactionCoordinator has been closed" does strongly hint in that direction. The reason for such an error could be a transaction timeout.

Which type of broker DB are you using? if it's SQL Server, then a tool like SQL Profiler can shine a light on what's happening on DB level and how long it takes.

Improve this answer
1
3

this is worker 135 of: 2226

That looks like a lot! Are there a lot of binaries being published as part of this transaction (you mention it is just 23 components and 93 items to publish according to the resolver)?

This is one of those types of errors that you need to identify by elimination so i'll just add my 2 cents: can you switch the deployer to be single threaded and try to reproduce? Just to eliminate a concurrency issue...

Improve this answer
1
  • Yes, lots of binaries.
    – ToddB
    Commented Jan 26, 2015 at 17:10

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.